Bug 10352

Summary: Performance of bitbake -S is horrible
Product: [Build System, Metadata & Runtime] BitBake Reporter: Richard Purdie <richard.purdie>
Component: bitbakeAssignee: Jianxun Zhang <jianxun.zhang>
Status: RESOLVED FIXED QA Contact:
Severity: enhancement    
Priority: High CC: jianxun.zhang, poky.bs.watcher, poky.watcher, sgw
Version: 2.3   
Target Milestone: 2.3 M2   
Hardware: x86   
OS: Multiple   
Whiteboard:
OS type for building Yocto: --- Type of Regression: ---
Verified: Documentation change: No (bug/feature does not impact docs)
Attachments:
Description Flags
possibly-irrelavant-bb-doesnot-take-cache-since-2nd-build.log
none
[HACK][WIP] Multi-processing dump signature routine
none
WRONG_DO_without_parsing_but_result_looks_okay.patch
none
[WIP] Multi-processing dump signature routine
none
0001-WIP-V3-Try-to-use-multiple-processes-to-dump-signatu.patch
none
Submitted: Patch for bz10352 none

Description Richard Purdie 2016-09-30 12:27:15 UTC
bitbake -S is slow. Its heavily used by sstate signature tests and is slow because it does a single threaded reparse. We should look at speeding it up to speed up selftests and -S usage (which will be important for automated YP Compatible testing).

We have to reparse in order to be able to generate accurate sigdata files. The base part of them can only be generated from a full data store which we don't retain in memory or disk after parsing. Sadly we also need the runtime data in order to write out a completely consistent file and this is only in the main bitbake process scope, not in the standard parser. This is why the current code ends up single threaded.
Comment 1 Jianxun Zhang 2016-10-03 17:26:10 UTC
I haven't work in bitbake so I take it as a start point.
Comment 2 Jianxun Zhang 2016-10-03 21:59:19 UTC
RP,
I could need some time to understand BB's internal flow and data structures. Hope you could provide some details like a test procedure so that we can quantify it.

I tried "bitbake -S printdiff core-image-minimal" and noticed it takes some time to finish after showing "NOTE: Reparsing files to collect dependency data" on my build host. Is this part we want to improve?

Thanks
Comment 3 Richard Purdie 2016-10-03 22:05:58 UTC
(In reply to comment #2)
> RP,
> I could need some time to understand BB's internal flow and data structures.
> Hope you could provide some details like a test procedure so that we can
> quantify it.
> 
> I tried "bitbake -S printdiff core-image-minimal" and noticed it takes some
> time to finish after showing "NOTE: Reparsing files to collect dependency
> data" on my build host. Is this part we want to improve?

That is the part we need to improve, yes. It comes from http://git.yoctoproject.org/cgit.cgi/poky/tree/bitbake/lib/bb/runqueue.py#n1297
which is dump_signatures() and some simple instrumentation or even just using the -P option to bitbake will show its spending a lot of time in that function for the reasons I described above.
Comment 4 Jianxun Zhang 2016-10-18 17:08:28 UTC
I have to give this task a big estimation though I believe the answer or solution is obvious for people expertise in this area. I feel I should have a solid understanding of the internal of logic and data structure prior to the first line of a new patch. Another necessary task is I should find some way to quantify the result and make sure to get same consistent data with new change.

In a short, you could not hear me back so often on this ticket when I am on the road.
Comment 5 Jianxun Zhang 2016-11-29 00:45:59 UTC
come back to this task after other stuffs reaching their milestones.

This finding doesn't indicate the issue tacked here, but could be worth as a side note. I run the same "bitbake -S none core-image-minimal" 3 times, started with a clean build dir. It seems bitbake takes cache from the 3rd test cycle instead of 2nd test cycle where I think everything should be already cached from the first clean run. I don't see this cause any change in -S "reparsing files..." stage however.
Comment 6 Jianxun Zhang 2016-11-29 00:48:11 UTC
Created attachment 3550 [details]
possibly-irrelavant-bb-doesnot-take-cache-since-2nd-build.log

attach the stdout of build for the finding in my previous comment.
Comment 7 Jianxun Zhang 2016-11-30 00:36:50 UTC
Created attachment 3551 [details]
[HACK][WIP] Multi-processing dump signature routine

I attached a shabby and unclean patch to exploit any cheap fruits. I actually don't know if it is the best way or could mess up any BB internals, just assuming there is no global data preventing us to do so.

It shorts the reparsing recipe stage from 13.3 to 1 second and a _sorted_ diff between generated locked-sigs.inc looks okay compared with a sorted original one.
Comment 8 Saul Wold 2016-11-30 05:20:34 UTC
Looking at the history of dump_signatures, I can see that prior to the multi-config change set this code used bb.cache.Cache, but after that change it changed to NoCache.

Similar to Chang's findings of parallelization, changing from NoCache to Cache based, improved performance greatly.

In both cases we have not done extensive testing, but confirmed that both options provide equivalent output in the locked-sig.ing file before and after the change. So getting a better understanding of the concern from the first comment about requiring a full re-generation of the data store is important.

I started oe-selftest runs before sending these comments, which are still in progress!
Comment 9 Richard Purdie 2016-11-30 16:09:04 UTC
(In reply to comment #8)
> Looking at the history of dump_signatures, I can see that prior to the
> multi-config change set this code used bb.cache.Cache, but after that change
> it changed to NoCache.
> 
> Similar to Chang's findings of parallelization, changing from NoCache to
> Cache based, improved performance greatly.
> 
> In both cases we have not done extensive testing, but confirmed that both
> options provide equivalent output in the locked-sig.ing file before and
> after the change. So getting a better understanding of the concern from the
> first comment about requiring a full re-generation of the data store is
> important.
> 
> I started oe-selftest runs before sending these comments, which are still in
> progress!

We can't benefit from the cache here which is why it uses NoCache. NoCache didn't exist before the multiconfig changes.

The reason we can't use the cache is that it doesn't store a full dependency tree for the signatures, it only stores the pieces between the basehash and the taskhash. In order to generate the data on how the basehash is constructed, we need to run the parse process.

I therefore thing that whilst putting "Cache" in here might appear to work and will make the locked-sigs.inc work just fine, it won't actually dump the siginfo/sigdata files onto the disk, or if it does, they won't contain all the dependency information and will be incomplete. The function is called "dump_sigs" and should write out this information.
Comment 10 Jianxun Zhang 2016-12-02 00:39:18 UTC
Created attachment 3554 [details]
WRONG_DO_without_parsing_but_result_looks_okay.patch

RP and Saul,
I upload a wrong-do patch which get rid of re-parsing. It still generates a locked-sig.inc with content seeming okay from manual check. The only difference is the order of dumped config sections. I cleaned build dir before these tests:

() rm -rf bitbake.lock cache downloads sstate-cache tmp
() bitbake -S none core-image-minimal

I definitely don't mean this is a solution for RP has suggested a need of reparsing. But the _problem_ indicated by the wrong-do patch is that I cannot tell if any agreed solution can effectively cover the potential issues without parsing. I have to find other validation procedures beyond merely checking the generated locked-sig.inc...

Or could there be some info already missed or wrong in dump with the current code tip?
Comment 11 Richard Purdie 2016-12-07 17:01:05 UTC
To illustrate what this command is meant to do, setup a clean build environment (empty TMPDIR), then run "bitbake -S printdiff bash".

What you will find is that as well as a locked-sigs.inc file, it will generate a lot of files under tmp/stamps/, for example:

build$ ls tmp/stamps/core2-64-poky-linux/bash/
4.3.30-r0.do_build.sigdata.89ebf459ff3470fc295cc38e3a5faecd                 4.3.30-r0.do_package.sigdata.2edc233f2e7ffb33f7b4d3f2f4b3450f
4.3.30-r0.do_compile_ptest_base.sigdata.f10144fbd8882d75ce9707a5f44ce584    4.3.30-r0.do_package_write_deb.sigdata.e0511ff32fc2a6d669c1ba8029f06790
4.3.30-r0.do_compile.sigdata.f3d738dd9645700afa50d9a712e9a163               4.3.30-r0.do_package_write_ipk.sigdata.1873c076fb45d7ddb5ffcec2fb53600d
4.3.30-r0.do_configure_ptest_base.sigdata.14342141d81f42cc3f0a68e44f61ecc8  4.3.30-r0.do_package_write_rpm.sigdata.51aeceb0e8ff9d493464ae5c6ae8d9fa
4.3.30-r0.do_configure.sigdata.af8a39a363f89d2227a183f4fbd94a40             4.3.30-r0.do_patch.sigdata.a79d188ede0adfdfbd2c48a2bb23aef7
4.3.30-r0.do_fetch.sigdata.fcf446621baa2a5bf46b4d65c1d8f720                 4.3.30-r0.do_populate_lic.sigdata.ea9a83ae3c7a2272aee8fcefccd5561a
4.3.30-r0.do_install_ptest_base.sigdata.bf5d925f1f8e7d9311562334edcc6169    4.3.30-r0.do_populate_sysroot.sigdata.7046ed309d0a76f79aa04b13f5fbc5d4
4.3.30-r0.do_install.sigdata.63c3fbed0335eb2e4036850dd344a0db               4.3.30-r0.do_prepare_recipe_sysroot.sigdata.d98f97fe7ef1fc3f85d9fc00af1ca463
4.3.30-r0.do_packagedata.sigdata.e9134c2dcd0e4b8a0a15f4ed1476fcf0           4.3.30-r0.do_unpack.sigdata.6b560a0430c4b7c163976643b5baa48c
4.3.30-r0.do_package_qa.sigdata.b4517b80c7bb6e1ff517a63a1837a30c

These files are only generated by a reparse and if the metadata is not reparsed, these files will either not be generated at all, or will be incomplete. Generating these files was the original point of this command, not the locked-sigs.inc file which in fact was a later addition. These sigdata files are used by sstate tests and other pieces of code and are very important, we need to generate them.
Comment 12 Jianxun Zhang 2016-12-07 20:29:28 UTC
RP,
Thanks lot to enlighten me. I tried the uploaded wip patch and it shows no stamps in build dir with same test. I guess this is what you meant in previous mail for why it is single threaded...

Let me hike more in BB with these hints for a right solution.
Comment 13 Jianxun Zhang 2016-12-13 01:29:21 UTC
Created attachment 3558 [details]
[WIP] Multi-processing dump signature routine

I uploaded another wip patch which seems getting good stamps and locked-sigs.inc with a multi-process solution. (reparing perf: 14.7sec -> 1.5sec) However I still cannot explain it very well since I am still hiking in BB to grasp its internal data and threading models.

Some notes here:
() Even this turns out to be the direction, the usage of processing of python is subject to change (to a queue or pool) when respecting BB_NUMBER_THREADS. This wip patch fires one process for every file to reparse!

() Each process outputs one "Writing locked sigs to..." line to screen because I moved dump_sig into sub-process. But the output seems no mixed up content at all. I am not sure if BB has some magic to lock the file to write, and I will check it. Also it should be worthy to check each process's dump respectively.
Comment 14 Jianxun Zhang 2016-12-13 20:22:35 UTC
Created attachment 3560 [details]
0001-WIP-V3-Try-to-use-multiple-processes-to-dump-signatu.patch

Okay, I get closer...

Upload a WIP [v3] patch which still has several items/questions to be addressed. The improvement in V3 is that we won't cause dumping locked-sig.inc (in OE) triggered multiple times.
Comment 15 Richard Purdie 2016-12-14 16:00:22 UTC
FWIW I think you're right with the "Maybe we should have a dump_sigfn() in siggen" comment, we don't want to duplicate that code as you have here. I think this does look like the approximate right direction. As you say, we need a BB_NUMBER_PARSE_THREADS pool of parsers (not BB_NUMBER_THREADS).
Comment 16 Jianxun Zhang 2016-12-20 00:46:57 UTC
RP & Saul,
I managed to have a patch to overcome obstacles on the road. I think it is close to a submission if you guys don't see any better solution.

http://git.yoctoproject.org/cgit/cgit.cgi/poky-contrib/commit/?h=jxzhang/bz10352-submission

Please let me know any test I could run to validate it, beside from seeing stamps and lock-sigs.inc generated.

I have other two patches as byproduct. They are _not_ related to this 10352:

http://git.yoctoproject.org/cgit/cgit.cgi/poky-contrib/log/?h=jxzhang/misc-sig-fixes

Maybe you can help to review them by any chance.
Comment 17 Jianxun Zhang 2016-12-20 17:08:34 UTC
I am thinking to use a better logic to replace the batch-launching in dump_signature(). I could fire processes continuously with checking is_alive() and a final join() at the end. (Still don't want to bother more complicated solutions...)

But the most in the uploaded gonna stay.
Comment 18 Jianxun Zhang 2016-12-20 20:30:11 UTC
Update patch for bz10352 to replace batch-launching progresses with a better approach. Go ahead with more tests:
http://git.yoctoproject.org/cgit/cgit.cgi/poky-contrib/commit/?h=jxzhang/bz10352-submission-1

(Recap) the other two patches as byproduct. They are _not_ related to this 10352:

http://git.yoctoproject.org/cgit/cgit.cgi/poky-contrib/log/?h=jxzhang/misc-sig-fixes
Comment 19 Jianxun Zhang 2016-12-21 20:27:21 UTC
Created attachment 3569 [details]
Submitted: Patch for bz10352

The attached is submitted to bitbake-devel@lists.openembedded.org
Comment 20 Jianxun Zhang 2016-12-21 20:28:45 UTC
Tested with sstatetest module in oe-selftest. The submitted has been attached in this ticket.
Comment 21 Jianxun Zhang 2016-12-21 22:33:26 UTC
The first of two by-product patches is submitted:

http://git.yoctoproject.org/cgit/cgit.cgi/poky-contrib/commit/?h=jxzhang/misc-sig-fixes&id=d75548a64eed6060d94e1ed145f07dfbc51f94da

The 2nd is in test.
Comment 22 Jianxun Zhang 2017-01-19 20:59:20 UTC
The patch has been merged into bitbake repo and integrated into poky master branch
http://git.yoctoproject.org/cgit/cgit.cgi/poky/commit/?id=7eb02e837ed253a2ae69023595c25660b4d56b7c