| Summary: | Upgrade to sqlite version 3.14.1 results in increased build time (performance related) | ||
|---|---|---|---|
| Product: | [Build System, Metadata & Runtime] OE-Core | Reporter: | Maxin B. John <maxin.john> |
| Component: | core | Assignee: | Jianxun Zhang <jianxun.zhang> |
| Status: | RESOLVED FIXED | QA Contact: | |
| Severity: | normal | ||
| Priority: | Medium+ | CC: | jku, meta.mr.watcher, meta.watcher, richard.purdie, seebs |
| Version: | 2.2 | ||
| Target Milestone: | 2.2 M4 | ||
| Hardware: | All | ||
| OS: | Multiple | ||
| Whiteboard: | |||
| OS type for building Yocto: | --- | Type of Regression: | --- |
| Verified: | Documentation change: | No (bug/feature does not impact docs) | |
| Bug Depends on: | |||
| Bug Blocks: | 9975 | ||
| Attachments: | |||
|
Description
Maxin B. John
2016-10-04 13:58:07 UTC
With sqlite version 3.14.1 /usr/bin/time -v bitbake core-image-minimal Parsing recipes: 100% |#################################################################################################################################################################################################################################################################################################################################################################################################| Time: 0:00:08 Parsing of 868 .bb files complete (0 cached, 868 parsed). 1319 targets, 51 skipped, 0 masked, 0 errors. NOTE: Resolving any missing task queue dependencies Build Configuration: BB_VERSION = "1.31.1" BUILD_SYS = "x86_64-linux" NATIVELSBSTRING = "Fedora-22" TARGET_SYS = "x86_64-poky-linux" MACHINE = "qemux86-64" DISTRO = "poky" DISTRO_VERSION = "2.1+snapshot-20161004" TUNE_FEATURES = "m64 core2" TARGET_FPU = "" meta meta-poky meta-yocto-bsp = "master:197e05f5978577ba511da47fe383481005fe60d9" Initialising tasks: 100% |##############################################################################################################################################################################################################################################################################################################################################################################################| Time: 0:00:03 NOTE: Executing SetScene Tasks NOTE: Executing RunQueue Tasks NOTE: Tasks Summary: Attempted 2356 tasks of which 10 didn't need to be rerun and all succeeded. Command being timed: "bitbake core-image-minimal" User time (seconds): 17227.75 System time (seconds): 2842.80 Percent of CPU this job got: 1061% Elapsed (wall clock) time (h:mm:ss or m:ss): 31:31.48 Average shared text size (kbytes): 0 Average unshared data size (kbytes): 0 Average stack size (kbytes): 0 Average total size (kbytes): 0 Maximum resident set size (kbytes): 917016 Average resident set size (kbytes): 0 Major (requiring I/O) page faults: 3594 Minor (reclaiming a frame) page faults: 720026641 Voluntary context switches: 17342063 Involuntary context switches: 11538115 Swaps: 0 File system inputs: 3356520 File system outputs: 59671104 Socket messages sent: 0 Socket messages received: 0 Signals delivered: 0 Page size (bytes): 4096 Exit status: 0 with sqlite version 3.14.2 /usr/bin/time -v bitbake core-image-minimal Parsing recipes: 100% |#################################################################################################################################################################################################################################################################################################################################################################################################| Time: 0:00:13 Parsing of 868 .bb files complete (0 cached, 868 parsed). 1319 targets, 51 skipped, 0 masked, 0 errors. NOTE: Resolving any missing task queue dependencies Build Configuration: BB_VERSION = "1.31.1" BUILD_SYS = "x86_64-linux" NATIVELSBSTRING = "Fedora-22" TARGET_SYS = "x86_64-poky-linux" MACHINE = "qemux86-64" DISTRO = "poky" DISTRO_VERSION = "2.1+snapshot-20161004" TUNE_FEATURES = "m64 core2" TARGET_FPU = "" meta meta-poky meta-yocto-bsp = "master:857ea0dbb6c2e61833026e868b596fae4d618d40" Initialising tasks: 100% |##############################################################################################################################################################################################################################################################################################################################################################################################| Time: 0:00:04 NOTE: Executing SetScene Tasks NOTE: Executing RunQueue Tasks NOTE: Tasks Summary: Attempted 2356 tasks of which 10 didn't need to be rerun and all succeeded. Command being timed: "bitbake core-image-minimal" User time (seconds): 17120.92 System time (seconds): 2803.17 Percent of CPU this job got: 1090% Elapsed (wall clock) time (h:mm:ss or m:ss): 30:26.33 Average shared text size (kbytes): 0 Average unshared data size (kbytes): 0 Average stack size (kbytes): 0 Average total size (kbytes): 0 Maximum resident set size (kbytes): 917004 Average resident set size (kbytes): 0 Major (requiring I/O) page faults: 6598 Minor (reclaiming a frame) page faults: 721608928 Voluntary context switches: 17901602 Involuntary context switches: 10378016 Swaps: 0 File system inputs: 3075816 File system outputs: 59675416 Socket messages sent: 0 Socket messages received: 0 Signals delivered: 0 Page size (bytes): 4096 Exit status: 0 Upgrade to 3.14.2 improves build time by 1 minute. upgrade to sqlite 3.14.2 patch is available here: http://git.yoctoproject.org/cgit/cgit.cgi/poky-contrib/commit/?h=maxin/sqlite3&id=7c87f62ca5459b39c86a73d8302ad9f7bbef3272 I can take a look at this, There aren't too many commits to go through. (... Fossil? where do people find these version control systems?) (In reply to comment #3) > I can take a look at this, There aren't too many commits to go through. Before I got to looking at the commits I tried to reproduce Maxins results and couldn't. Averages from 3 builds with each sqlite version (core-image-minimal with clean tmp and sstate): sqlite build time 3.12.2: 30:03 3.14.1: 30:32 3.14.2: 30:28 The difference between the latter two does not seem significant (statistically or otherwise). Even with 3.12.2 the differences are small enough that this is probably not a great benchmark. I am doing some benchmark across sqlite3 versions today. The first corner case (not very possible) to exclude is any weirdo shows up when building sqlite3-native and pseudo-native _themselves_ prior to any task calling them. Average of 5 measurement is: sqlite 3.14.1 + pseudo: 56.8340s sqlite 3.12 + pseudo: 56.8298s No significant finding in data with other pieces kept same and built. I am doing another benchmark to identify any runtime regression when pseudo compiled with different sqlite3 versions. Regarding to the different results from Jussi and Maxin, it seems Marxin's test is from incremental build but Jussi's looks like from clean build(?). I am no sure if this could explain the difference however. I will upload my data with minimal image soon. (In reply to comment #5) > Regarding to the different results from Jussi and Maxin, it seems Marxin's > test is from incremental build but Jussi's looks like from clean build(?). I > am no sure if this could explain the difference however. It was the result from clean builds (wiped tmp and sstate before each build). Created attachment 3455 [details]
bz10367-core-minimal-build-time-sqlite3-poky-base-3a73fe0efcb7a.pdf
I benchmarked build time with different sqlite3 versions with the same latest poky tip. In a short:
I don't see significant difference between 3.14.2 and 3.13. Both of them show about 2% increase on build time compared with 3.12. Issue is still here.
Perhaps you guys can have a look at test procedure for anything I missed.
Ref to attachment:
bz10367-core-minimal-build-time-sqlite3-poky-base-3a73fe0efcb7a.pdf
I've done some more testing on the side:
* I can still see a small build time difference on core-image-minimal (1800 sec for sqlite 3.12.2 vs. 1830 sec for sqlite 3.14.1).
* I cannot figure out how to reproduce this on a specific task ("bitbake -f -c package perl" takes just as long on both versions)
Interesting observation that may be related but happens on both versions: if I do this (when perl install task is already done):
$ time bitbake -f -c package perl; time bitbake -f -c package perl
the first package is 30% faster than any subsequent ones. I've confirmed this is related to the pseudo database: If I replace the pseudo db with a copy taken just after install task, package is fast again. The difference is in wallclock time (sys+user do not change) -- this seems reasonable if pseudo runs in another process.
Maybe the above is expected (db access gets slower as it grows) but it does show pseudo is definitely a bottleneck here.
Created attachment 3458 [details]
Test Summary: 2% increase build time caused by sqlite library
With new test 3 and 4 in updated report, I think we now have more statistic data to show a consistent 2% increase of build time and it is very possibly caused by library of sqlite3 between 3.12.2 and 3.13.
I will do some bisect in sqlite3 to pin point the changes cause it.
Adding seebs to CC: I wonder if you have any insight -- either on how to better benchmark the apparent pseudo slowdown resulting from new sqlite or on the curious results I mentioned in comment 8. The first thing I'd probably poke at is pseudo's configuration settings for things like use/don't-use in-memory database. Because I know that the in-memory database behaved pathologically (much slower than disk!) with sqlite 3.6 or so, and it could well be that this comes and goes. The behavior being slower with an existing database is pretty expected. Worth looking to see whether pseudo.log is full of noise for that -- if it is, it's possible we're corrupting things (say, removing files from disk but leaving them in the pseudo database), and that *will* make things slower. Pseudo has a fair amount of instrumentation/profiling stuff available. See pseudo_profile and the PSEUDO_PROFILE_PATH environment variable. My expectation would be that you'd see all the change be reflected in the IPC time numbers, because presumably all the processing is happening server-side. (You could also look at pseudo.log for pseudo's message handling and time statistics.) ... I should point out, at this point, my suspicion is that the largest slowdowns in pseudo are NOT in the IPC or database, but actually in the client code. (In reply to comment #11) > The behavior being slower with an existing database is pretty expected. > Worth looking to see whether pseudo.log is full of noise for that -- if it > is, it's possible we're corrupting things (say, removing files from disk but > leaving them in the pseudo database), and that *will* make things slower. It's indeed full of spam: the perl pseudo.log is 4MB of lines like | path mismatch [1 link]: ino 4328585 db 'NAMELESS FILE' req '/mnt/extra-ssd/tmp/work/core2-64-poky-linux/perl/5.22.1-r0/perl-5.22.1/hints/cxux.sh'. and | path mismatch [2 links]: ino 1325329 db '/mnt/extra-ssd/tmp/work/core2-64-poky-linux/perl/5.22.1-r0/pkgdata/runtime/perl-module-config-git' req '/mnt/extra-ssd/tmp/sysroots/qemux86-64/pkgdata/runtime/perl-module-config-git'. Okay, the second one is probably harmless, but the first one is really interesting, because that implies that a file somehow made it into the db without a name, and that's not supposed to be an easy thing. Probably unrelated, but still interesting. This is just an intermediate update. I am bisecting in sqlite3 after overcoming the particularities in sqlite3 project. It could take me 1~2 days to finish bisecting because of the build time of multiple build in a single iteration. Created attachment 3469 [details]
Bisect Result: ad601c7962 in sqlite introduced +2% of build time
I have traced to change ad601c7962 "For in-memory databases, it does not matter if pcache entries are marked "clean" or "writable". (user: drh tags: pager-dev)" introduced this 2% increase of built time.
Refer to the data in this attachment.
I will try to revert this change in sqlite3 amalgamation package in OE.
Interesting. It may also be worth tweaking pseudo to not try to use in-memory databases, as I'm not actually sure how much performance gain they provide. (There's a configure option for that.) Created attachment 3470 [details]
Bisect Result & Test Result of reverting ad601c7962 in sqlite3
I roll the test result of a revert patch which seems bring the build time back to 3.12.2 level.
I am going to attach the WIP patch and wrap-up with another update.
Created attachment 3471 [details]
WIP Patch: Fix 2% increase of build time by sqlite3
Refer to the previous comment for the result of build time. I think this patch fixed 2% increase of build time at least.
Without knowing much about the internal of sqlite3, what I can do is to put this patch under some limited test before submission. And it could be worthy to ask sqlite developers in their mailing list for what I found in YP build. So far from the change comment I don't feel the reverted change was a critical fix.
I have submitted a formal patch of the same change to OE today. http://lists.openembedded.org/pipermail/openembedded-core/2016-October/127559.html Add link of V2 for reference. http://git.yoctoproject.org/cgit/cgit.cgi/poky/commit/?id=7052400ceadd309a11c3c8dd2b2a4879d69aac02 Patch has been merged into master branch in poky. Change state to "Resolved". |