| Summary: | Analyse performance regression against 2.1 | ||||||
|---|---|---|---|---|---|---|---|
| Product: | [Build System, Metadata & Runtime] OE-Core | Reporter: | Ross Burton <ross.burton> | ||||
| Component: | core | Assignee: | Markus Lehtonen <markus.lehtonen> | ||||
| Status: | RESOLVED FIXED | QA Contact: | |||||
| Severity: | major | ||||||
| Priority: | Medium+ | CC: | bluelightning, eduard.bartosh, jianxun.zhang, joshuagloe, maxin.john, meta.mr.watcher, meta.watcher, richard.purdie, sgw | ||||
| Version: | 2.1 | ||||||
| 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: | 10367, 10386 | ||||||
| Bug Blocks: | |||||||
| Attachments: |
|
||||||
|
Description
Ross Burton
2016-07-19 13:46:52 UTC
Ed, you've been looking at this over the last week, what are your conclusions so far? I've noticed 2 serious performance regressions:
1. gcc upgrade increased build time of core-image-minimal to around 3%:
one commit before bumping gcc: 2718e843b3502afa1e21510bb6b9c4720f75124c +0.31%
Command being timed: "bitbake core-image-minimal"
User time (seconds): 10248.53
System time (seconds): 843.68
Percent of CPU this job got: 601%
Elapsed (wall clock) time (h:mm:ss or m:ss): 30:44.21
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): 807312
Average resident set size (kbytes): 0
Major (requiring I/O) page faults: 2545
Minor (reclaiming a frame) page faults: 577796008
Voluntary context switches: 16200753
Involuntary context switches: 12528911
Swaps: 0
File system inputs: 3208488
File system outputs: 47013800
Socket messages sent: 0
Socket messages received: 0
Signals delivered: 0
Page size (bytes): 4096
Exit status: 0
Bump gcc 6.1: 239efccccaa74912b3fc9ec717e93f528e2c3836 +3.27%
Command being timed: "bitbake core-image-minimal"
User time (seconds): 10567.75
System time (seconds): 851.97
Percent of CPU this job got: 606%
Elapsed (wall clock) time (h:mm:ss or m:ss): 31:23.53
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): 916736
Average resident set size (kbytes): 0
Major (requiring I/O) page faults: 3404
Minor (reclaiming a frame) page faults: 580093046
Voluntary context switches: 15581624
Involuntary context switches: 12004959
Swaps: 0
File system inputs: 3903592
File system outputs: 49077408
Socket messages sent: 0
Socket messages received: 0
Signals delivered: 0
Page size (bytes): 4096
Exit status: 0
This regression influenced almost all tasks, so I doubt we can do anything about it.
2. Enabling kernel printk feature increased build time of core-image-minimal around 2.7%
You can see more details in this ml thread: http://lists.openembedded.org/pipermail/openembedded-core/2016-July/124378.html
This is about to be fixed. the fix is already under review:
http://lists.openembedded.org/pipermail/openembedded-core/2016-July/124466.html
I'm testing it. Will comment on the thread and here about results when I'm done.
The fix has been merged to yocto-4.4 branch of yocto-kernel-cache: https://git.yoctoproject.org/cgit/cgit.cgi/yocto-kernel-cache/commit/?h=yocto-4.4&id=d3cc76c3cb20247b16c16b2367decf08b5fb90fa And included into last kernel update: http://lists.openembedded.org/pipermail/openembedded-core/2016-July/124466.html With the fix applied kernel build time decreased by 22.84%: Build Configuration: BB_VERSION = "1.31.0" BUILD_SYS = "x86_64-linux" NATIVELSBSTRING = "openSUSE-13.2" TARGET_SYS = "i586-poky-linux" MACHINE = "qemux86" DISTRO = "poky" DISTRO_VERSION = "2.1+snapshot-20160728" TUNE_FEATURES = "m32 i586" TARGET_FPU = "" meta meta-poky meta-yocto-bsp = "master:039f47ad197a9a53109c9f3deadd9c35e62c056d" before the fix: Command being timed: "bitbake virtual/kernel" User time (seconds): 1367.06 System time (seconds): 162.06 Percent of CPU this job got: 372% Elapsed (wall clock) time (h:mm:ss or m:ss): 6:50.56 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): 627120 Average resident set size (kbytes): 0 Major (requiring I/O) page faults: 1292 Minor (reclaiming a frame) page faults: 61097551 Voluntary context switches: 885976 Involuntary context switches: 715312 Swaps: 0 File system inputs: 1024568 File system outputs: 13316088 Socket messages sent: 0 Socket messages received: 0 Signals delivered: 0 Page size (bytes): 4096 Exit status: 0 after the fix: Command being timed: "bitbake virtual/kernel" User time (seconds): 1050.97 System time (seconds): 128.84 Percent of CPU this job got: 434% Elapsed (wall clock) time (h:mm:ss or m:ss): 4:31.35 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): 387148 Average resident set size (kbytes): 0 Major (requiring I/O) page faults: 1264 Minor (reclaiming a frame) page faults: 52467379 Voluntary context switches: 589830 Involuntary context switches: 457987 Swaps: 0 File system inputs: 1107424 File system outputs: 3363464 Socket messages sent: 0 Socket messages received: 0 Signals delivered: 0 Page size (bytes): 4096 Exit status: 0 And consumed disk space decreased by 89.62%: before the fix: $ du -sh tmp/work/qemux86-poky-linux/linux-yocto/4.4.14+gitAUTOINC+4800a400d5_8361321fec-r0/deploy-linux-yocto/ 106M after the fix: $ du -sh tmp/work/qemux86-poky-linux/linux-yocto/4.4.14+gitAUTOINC+86bf91f444_8361321fec-r0/deploy-linux-yocto/ 11M There is still noticeable regression in build time between krogoth and master even not counting gcc upgrade, but unfortunately it's hard to bisect.
The difference is about 5.42% (gcc upgrade 3% regression included):
krogoth: 98c57bb512ea6790db8604fcf0b88c81651d2ab4
Command being timed: "bitbake core-image-minimal"
User time (seconds): 13664.25
System time (seconds): 3676.42
Percent of CPU this job got: 1193%
Elapsed (wall clock) time (h:mm:ss or m:ss): 24:12.46
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): 808236
Average resident set size (kbytes): 0
Major (requiring I/O) page faults: 6003
Minor (reclaiming a frame) page faults: 590008594
Voluntary context switches: 26319785
Involuntary context switches: 1829105
Swaps: 0
File system inputs: 2846240
File system outputs: 60929392
Socket messages sent: 0
Socket messages received: 0
Signals delivered: 0
Page size (bytes): 4096
Exit status: 0
master with the kernel fix applied manually: 039f47ad197a9a53109c9f3deadd9c35e62c056d
Command being timed: "bitbake core-image-minimal"
User time (seconds): 14569.65
System time (seconds): 3711.03
Percent of CPU this job got: 1213%
Elapsed (wall clock) time (h:mm:ss or m:ss): 25:05.91
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): 917772
Average resident set size (kbytes): 0
Major (requiring I/O) page faults: 8118
Minor (reclaiming a frame) page faults: 622000924
Voluntary context switches: 18639324
Involuntary context switches: 1847441
Swaps: 0
File system inputs: 3191592
File system outputs: 47418720
Socket messages sent: 0
Socket messages received: 0
Signals delivered: 0
Page size (bytes): 4096
Exit status: 0
Some numbers comparing 2.1.1 with master from one of the autobuilders: ypperf02,(HEADdetachedatf5da2a5):f5da2a5913319ad6ac2141438ba1aa17576326ab,krogoth-15.0.0-212-gf5da2a5,57:51.81,4:06.57,57:26.60,2:02.54,0:14.79,0:09.75,0:01.13,2:36.55,25401936,5415940,1282886,4786477 ypperf02,(HEADdetachedatf5da2a5):f5da2a5913319ad6ac2141438ba1aa17576326ab,krogoth-15.0.0-212-gf5da2a5,56:29.21,4:14.75,56:33.10,2:13.42,0:14.76,0:09.97,0:01.07,2:36.51,25400748,5415756,1283061,4786623 ypperf02,(HEADdetachedatf5da2a5):f5da2a5913319ad6ac2141438ba1aa17576326ab,krogoth-15.0.0-212-gf5da2a5,56:36.68,4:08.35,56:59.47,2:08.62,0:14.62,0:10.38,0:01.22,2:36.66,25401892,5415728,1282998,4786626 ypperf02,(HEADdetachedatf5da2a5):f5da2a5913319ad6ac2141438ba1aa17576326ab,krogoth-15.0.0-212-gf5da2a5,56:38.42,4:05.47,56:57.02,2:03.41,0:14.59,0:09.77,0:01.08,2:35.08,25400900,5415728,1283066,4786630 ypperf02,(HEADdetachedatf5da2a5):f5da2a5913319ad6ac2141438ba1aa17576326ab,yocto-2.1.1,57:02.88,4:06.96,57:19.02,2:05.43,0:14.66,0:09.79,0:01.07,2:39.22,25401604,5415920,1282963,4786567 ypperf02,(HEADdetachedatf5da2a5):f5da2a5913319ad6ac2141438ba1aa17576326ab,yocto-2.1.1,56:49.96,4:08.19,56:51.28,2:14.09,0:14.77,0:09.76,0:01.14,2:49.36,25403612,5415768,1282860,4786639 ypperf02,(HEADdetachedatf5da2a5):f5da2a5913319ad6ac2141438ba1aa17576326ab,yocto-2.1.1,56:34.36,4:09.11,56:51.19,2:09.10,0:14.59,0:10.08,0:01.07,2:37.05,25401404,5415640,1283272,4786646 ypperf02,master:6b66e9317f4ec3a69f98f29836aafa35b52f3fc7,uninative-1.3,1:01:46,4:21.62,1:01:31,2:12.09,0:16.19,0:11.14,0:01.22,5:22.37,26660600,6418296,1477475,5440033 ypperf02,master:6b66e9317f4ec3a69f98f29836aafa35b52f3fc7,uninative-1.3,1:02:17,4:22.33,1:01:40,2:10.13,0:16.32,0:11.00,0:01.20,5:35.43,26663080,6418300,1477026,5439533 ypperf02,master:6b66e9317f4ec3a69f98f29836aafa35b52f3fc7,uninative-1.3,1:01:27,4:23.72,1:01:44,2:17.43,0:16.18,0:11.24,0:01.22,5:44.19,26662208,6418024,1477277,5439823 ypperf02,master:6b66e9317f4ec3a69f98f29836aafa35b52f3fc7,uninative-1.3,1:02:02,4:26.63,1:01:29,2:16.40,0:16.17,0:11.17,0:01.21,5:20.38,26660756,6419592,1477189,5440337 Basically, builds take around 5 minutes longer, parsing from cold is ~1.5s slower, hot parsing is around 1s slower, or disk footprint is around 1GB larger, our from sstate footprint has increased by 1G too (5.4->6.4), and esdk installation time has gone from 2.5mins to 5.5mins. This doesn't look good. Created attachment 3368 [details]
build perf regressions
Not nice :( I quickly put the numbers into an excel sheet. Build-time regression is ~8% on average, parsing regression ~10%
I'd suggest that another approach here might be to look into the disk usage changes. Those are much easier to bisect and might hint at where the performance degradations came from. We'll split the esdk regressions into a separate bug that Paul will look at. Looking into the core-image-sato build time, I found that one culprit seems to be commit ce376577a963ce2d906a5b4fac756d57e3c4353d Author: Maxin B. John <maxin.john@intel.com> Date: Mon May 23 18:39:56 2016 +0300 sqlite3: update to 3.13.0 3.12.2 -> 3.13.0 In my tests it seems to cause about 2% increase in the build time. I'm running another bisect on the build times to see if I can find something else. After that I will take a look at the eSDK installation time and disk usage. I studied the eSDK deploy time a bit. In my setup the regression is about 89% (4:30 -> 8:30). It seems that about 3 minutes of that regression (66% regression) is caused by: commit f3b62c1c2e47968084342d1fe2a9af596a3ba93c Author: Paul Eggleton <paul.eggleton@linux.intel.com> Date: Thu Jun 23 22:59:11 2016 +1200 bitbake: runqueue: add ability to enforce that tasks are setscened My test result suggest that the rest of the eSDK install time regression happened was caused by the Python3 transition (between fa4275b..a15e538) (In reply to comment #10) > My test result suggest that the rest of the eSDK install time regression > happened was caused by the Python3 transition (between fa4275b..a15e538) As such, a performance regression caused by simply a transition to Python3 sounds strange. One problem is that further bisecting is not possible because poky is in unbuildable state between fa4275b..a15e538. I also examined bitbake parsing time. It seems that the regression is caused by (at least mostly) during Python3 transition (52c4b7f..0f2c593). Regarding parsing times, Python3 seems to be the issue. There are very small regression over time but they are hard to pinpoint. I think they're just caused by adding new files that need to be parsed, e.g. commit 6ea164c208ab43251544525e83644a8f84d3a6f8 Author: Khem Raj <raj.khem@gmail.com> Date: Wed May 11 10:35:04 2016 -0700 gcc: Add gcc6 recipes AR to Markus for a status update :) A recap from my findings so far. 1. core-image-sato build time About half of the regression is caused by gcc6. One fourth is caused by upgradeing sqlite to 3.13.0. I'm missing data for the last quarter. 2. bitbake parsing time Caused by Python3 transition (somewhere between 52c4b7f..0f2c593). Also slight increase because of new files to be parsed (e.g. addition of gcc6). 3. eSDK About 2/3 of the regression is caused by f3b62c1 (bitbake: runqueue: add ability to enforce that tasks are setscened). The rest of the regression is because of Python3 (somewhere between fa4275b..a15e538) I realized that I've still some work to do on bisecting core-image-sato. I'll give you some numbers on that shortly. Can you elaborate on the sqlite3 impact? In a quick comparison here using buildstats-diff, 3.14 is 1s faster to compile than 3.12 which may well be noise. Regarding sqlite, I hadn't analyzed the regression more deeply. Now that I looked at that I saw the same thing: build time of sqlite itself is even shorter after the update. Somehow the update affects the overall build time of other packages. Not cputime but the wall clock time. I developed my tooling (buildstats-diff) a bit and got the following data: $ buildstats-diff buildstats-40233_g9ade84b-20160921_184610 buildstats-40234_gce37657-20160921_220750 --multi --diff-attr=walltime --min-absdiff=15 INFO: Averaging over 3 buildstats from buildstats-40233_g9ade84b-20160921_184610 INFO: Averaging over 3 buildstats from buildstats-40234_gce37657-20160921_220750 Ignoring tasks less than 00:05.0 (5.0s) Ignoring differences less than 00:15.0 (15.0s) PKG TASK ABSDIFF RELDIFF WALLTIME1 -> WALLTIME2 ncurses do_package_qa -25.8s -77.3% 33.4s -> 7.6s ncurses do_install -22.6s -34.6% 65.4s -> 42.8s db do_package_qa -21.5s -48.7% 44.1s -> 22.6s binutils do_compile -19.8s -10.7% 185.5s -> 165.7s openssl do_compile -18.8s -13.9% 135.1s -> 116.3s gcc-cross-i586 do_compile -18.4s -10.4% 177.4s -> 159.0s gtk+ do_compile -16.5s -5.5% 297.6s -> 281.1s sqlite3 do_compile -15.4s -18.9% 81.2s -> 65.8s ncurses do_package 15.6s +68.1% 22.9s -> 38.5s rpm-native do_configure 16.4s +5.7% 288.0s -> 304.4s perl do_patch 16.9s +161.9% 10.4s -> 27.3s openssl do_install 18.2s +29.7% 61.1s -> 79.3s adwaita-icon-theme do_package 18.3s +53.4% 34.2s -> 52.5s linux-yocto do_patch 19.2s +93.4% 20.6s -> 39.8s gettext do_package_qa 19.2s +82.9% 23.2s -> 42.4s db do_package 20.3s +60.8% 33.4s -> 53.7s ncurses do_package_write_rpm 22.1s +271.8% 8.1s -> 30.2s adwaita-icon-theme do_install 27.2s +6.8% 397.3s -> 424.5s glib-2.0 do_package 27.6s +34.2% 80.6s -> 108.2s db do_package_write_rpm 36.4s +159.3% 22.9s -> 59.3s glibc-locale do_package_qa 40.5s +32.3% 125.1s -> 165.6s glibc-locale do_package_write_rpm 42.0s +16.6% 252.7s -> 294.7s libxml2 do_package 43.5s +31.2% 139.7s -> 183.2s glibc-locale do_package 107.9s +62.7% 172.2s -> 280.1s perl do_package 161.0s +92.1% 174.7s -> 335.8s Cumulative walltime: 683.6s +2.9% 6:27:04.3 (23224.3s) -> 6:38:27.9 (23907.9s) It seems that glibc-locale and perl are especially badly affected but I don't know why. I looked at the io stats but they didn't reveal anything obvious. One of the big users of sqlite is pseudo. Its possible the new version of sqlite contains something which slows it down and a slower pseudo would slow down pseudo using tasks like do_install and do_package. It shouldn't change do_compile or do_patch as these are not run under pseudo. Oh, pseudo could explain it. I did some more verification: I compared current master to current master with sqlite downgraded to 3.12.2. The end result is that with 3.12.2 the build time is faster - regression being ~2%. I investigated the tmpdir footprint. It seems that the biggest culprit is gcc6:
commit 239efccccaa74912b3fc9ec717e93f528e2c3836
tcmode-default: Bump gcc
gcc 6.1
In my setup tmpdir size is increased from 25.7GB to about 26.7GB
Then there are smaller changes, e.g.
commit 141fa73f97d72e074f7c1a3ce1efe1cd84f07b78
...
commit 5a3a4a7fbb1b2140a739f0282ff5740750b7185e
Python3 transition
26.7GB --> 27.3GB
commit e4738fdb8fae3a10c9f879bf2a768352ad68f669
matchbox-terminal: Upgrade to 0.1
27.4GB --> 27.7GB
commit e6c48b1213848757c3d3806a1985756bd7d5f30d
qemu: 2.6.0 -> 2.7.0
26.8GB --> 27.0GB
One notable decresase in size of tmpdir:
commit 30ab044dacf2b8ece625c0735b620b2c47b8cf40
binutils: Bump to 2.27
27.6GB --> 26.7GB
So, the end result is that gcc6 and Python3 seem to be the biggest contributors to the increase in tmpdir footprint. On top of that there are numerous commits each of which increase the footprint slightly, many of them some tens of megabytes.
With sqlite Version 3.14.1: 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 After upgrade to sqlite Version 3.14.2 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 Observed speedup for core-image-minimal is around 1 minute. split the sqlite part and mark this as depend on sqlite build performance bug (#10367) I took a look at the eSDK deploy footprint, too. OVerall, the size has increased from cs. 4.5GiB to ca. 5.2GiB. I found two points of regression.
commit 239efccccaa74912b3fc9ec717e93f528e2c3836
tcmode-default: Bump gcc
gcc 6.1
4.55GiB --> 4.83GiB
There's a bigger increase somewhere between 4071217...0e3281f:
4.75GiB --> 5.31GiB
However, eSDK is in unbuildable state between those commits because of the progress bar stuff so no more details. Analyzing it further would require re-ordering the commits to make it buildable again. I quickly tried this but stopped when patches didn't apply cleanly.
Note that we merged the sqlite regression fix mentioned in comment 22 (bug 10367). CCing Paul for any opinions on Markus's comments in comment 23. In particular oe-core 2b9c092 is in that range and adds more dependencies to the eSDK. One way to get results between those two commits would be to rebase and simply drop all of the progress stuff - since it's unlikely that would be impacting the size. The rest of the regression (i.e. other than what was caused by sqlite and eSDK changes) seem to be because of gcc6 and Python3. I guess we cannot do much about those, at least in 2.2 timeframe. That is, Python3 transition and gcc6 seems to cause at most of the regression in the sato build time. Closing this as we've analyzed the regressions and fixed what we can for 2.2. Some notes from Richard: http://lists.openembedded.org/pipermail/openembedded-core/2016-October/127825.html |