TipsAndTricks/MiningPerformanceData
Mining Performance Data
Looking at a performance report such as https://wiki.yoctoproject.org/charts/build_perf/latest/ypperf-fedora25_master_qemux86.html you might notice a change which would be interesting to get more data on. At the time of writing there was a big build performance regression from build 49367 to 49387. The report at the time would have summarised the buildstats difference but if that is not readily available or doesn't have enough detail, the buildstats can be recovered and compared.
First, clone the performance data archives from https://git.yoctoproject.org/cgit/cgit.cgi/yp-qa-build-perf-data/.
We're interested in the host ypperf-fedora25, branch master, commits 49367 and 49387. We can mine this data by using oe-build-perf-report, from oe-core.
$ oe-build-perf-report --repo /path/to/yp-qa-build-perf-data/ --hostname ypperf-fedora25 --branch master --commit-number 49387 --commit-number2 49367
TEST METADATA:
==============
CURRENT COMMIT COMPARING WITH
Hostname: ypperf-fedora25 ypperf-fedora25
Branch: master master
Commit number: 49387 49367
Commit: 0fa0baed74dfc1d0b424 83cd2b3e775235942dd4
Number of test runs: 1 4
TEST RESULTS:
=============
test1: Build core-image-sato
build time 1:40:13 -> 1:42:07 +1:54.1 +1.9 %
tmpdir size 31.09 GiB -> 34.31 GiB +3.22 GiB +10.3 %
test12: Build virtual/kernel
build time 8:52.8 -> 11:28.3 +2:35.5 +29.2 %
test13: Build core-image-sato with rm_work enabled
build time 1:40:32 -> 1:42:25 +1:53.6 +1.9 %
tmpdir size 6.05 GiB -> 9.27 GiB +3.22 GiB +53.2 %
test2: Run core-image-sato do_rootfs with sstate
do_rootfs time 3:08.3 -> 3:10.6 +2.4 s +1.3 %
test3: Bitbake parsing (bitbake -p)
parse_1 time 29.0 s -> 29.1 s +0.09 s +0.3 %
parse_2 time 18.5 s -> 18.5 s -0.07 s -0.4 %
parse_3 time 1.7 s -> 1.7 s +0.00 s +0.1 %
test4: eSDK metrics
installer_bin size 1.04 GiB -> 1.24 GiB +203.49 MiB +19.1 %
deploy time 3:14.2 -> 3:21.2 +7.0 s +3.6 %
deploy_dir size 3.45 GiB -> 3.85 GiB +409.38 MiB +11.6 %
That's the one: looking at just test1 (building core-image-sato from scratch) build time went up by two minutes and the tmpdir grew by 3GB. Presumably, these are related.
The top of the report has some details about the two commits that were being compared, including the actual SHAs instead of commit numbers. These can be used to examine the commits that were introduced between the tests.
We can dive into the buildstats by telling oe-build-perf-report to extract the buildstats using --dump-buildstats. These are also in the git repository but due to their size they are not fetched by default.
$ oe-build-perf-report --repo /path/to/yp-qa-build-perf-data/ --hostname ypperf-fedora25 --branch master --commit-number 49387 --commit-number2 49367 --dump-buildstats ERROR: No buildstats found, please try running 'git fetch origin refs/notes/buildstats/ypperf-fedora25/master/qemux86:refs/notes/buildstats/ypperf-fedora25/master/qemux86' to fetch them from the remote
Run that command and get lunch whilst it fetches, then try oe-build-perf-report again. This time it will write a oe-build-perf-buildstats directory with the raw data in:
oe-build-perf-buildstats/test13.build/ypperf-fedora25_master_qemux86_49387-g0fa0baed74dfc1d0b4245fd7c552a55c12ce6b23 oe-build-perf-buildstats/test13.build/ypperf-fedora25_master_qemux86_49387-g0fa0baed74dfc1d0b4245fd7c552a55c12ce6b23/0.json oe-build-perf-buildstats/test13.build/ypperf-fedora25_master_qemux86_49367-g83cd2b3e775235942dd4201622dc5cc2d4328994 oe-build-perf-buildstats/test13.build/ypperf-fedora25_master_qemux86_49367-g83cd2b3e775235942dd4201622dc5cc2d4328994/2.json oe-build-perf-buildstats/test13.build/ypperf-fedora25_master_qemux86_49367-g83cd2b3e775235942dd4201622dc5cc2d4328994/3.json oe-build-perf-buildstats/test13.build/ypperf-fedora25_master_qemux86_49367-g83cd2b3e775235942dd4201622dc5cc2d4328994/0.json oe-build-perf-buildstats/test13.build/ypperf-fedora25_master_qemux86_49367-g83cd2b3e775235942dd4201622dc5cc2d4328994/1.json oe-build-perf-buildstats/test1.build/ypperf-fedora25_master_qemux86_49387-g0fa0baed74dfc1d0b4245fd7c552a55c12ce6b23 oe-build-perf-buildstats/test1.build/ypperf-fedora25_master_qemux86_49387-g0fa0baed74dfc1d0b4245fd7c552a55c12ce6b23/0.json oe-build-perf-buildstats/test1.build/ypperf-fedora25_master_qemux86_49367-g83cd2b3e775235942dd4201622dc5cc2d4328994 oe-build-perf-buildstats/test1.build/ypperf-fedora25_master_qemux86_49367-g83cd2b3e775235942dd4201622dc5cc2d4328994/2.json oe-build-perf-buildstats/test1.build/ypperf-fedora25_master_qemux86_49367-g83cd2b3e775235942dd4201622dc5cc2d4328994/3.json oe-build-perf-buildstats/test1.build/ypperf-fedora25_master_qemux86_49367-g83cd2b3e775235942dd4201622dc5cc2d4328994/0.json oe-build-perf-buildstats/test1.build/ypperf-fedora25_master_qemux86_49367-g83cd2b3e775235942dd4201622dc5cc2d4328994/1.json
Directory per test, per commit, and each file is a test run as the performance machines will repeatedly build the same commit if there are not new commits to test. Note that these JSON files are not the same format as the buildstats files written by bitbake, but the data is the same and the tools work with both.
Looking again at test1, we can compare the buildstats using buildstats-diff:
$ buildstats-diff oe-build-perf-buildstats/test1.build/*49367*/ oe-build-perf-buildstats/test1.build/*49387*/ --multi INFO: Averaging over 4 buildstats from oe-build-perf-buildstats/test1.build/ypperf-fedora25_master_qemux86_49367-g83cd2b3e775235942dd4201622dc5cc2d4328994/ Ignoring tasks less than 00:03.0 (3.0s) Ignoring differences less than 00:01.0 (1.0s) PKG TASK ABSDIFF RELDIFF CPUTIME1 -> CPUTIME2 [ ... ] linux-yocto do_package 32.6s +128.1% 25.5s -> 58.1s linux-yocto do_deploy 41.6s +1653.3% 2.5s -> 44.1s linux-yocto do_package_write_rpm 233.1s +584.4% 39.9s -> 273.0s linux-yocto do_compile_kernelmodules 234.1s +16.4% 1429.9s -> 1664.0s linux-yocto do_compile 295.3s +18.5% 1599.1s -> 1894.4s
Root-caused: a change to the kernel caused it to take 530s longer to compile, and 230s longer to write the RPMs.
Now we can look at the git log for the revisions in this range (using the SHAs in the performance report summary):
$ git log --format=oneline 0fa0baed74dfc1d0b424...83cd2b3e775235942dd4 0fa0baed74dfc1d0b4245fd7c552a55c12ce6b23 python3: Fix install purelib to make pip3-python work properly 0d4459e7086fced5e9e0b4ad10378c9eddec56a8 package_manager.py: Explicit complementary fail 8e3839ce2663715de7f5d67ab21041b9e60e6efb linux-yocto/4.12: warning: drm/i915/cfl: Coffee Lake works on Kaby Lake PCH a7c9bc7020ab4c62fa60eb23257f07734b2582b0 linux-yocto: aufs and systemtap 3a8cce8b5c224710660802fba2bc0bbc97cf7385 linux-yocto/4.12: memleak and build warning fixes 266b2d16fcc7290d6fc6ff50d3ab974149bd8ebb linux-yocto/4.12: fix aufs compile warning b4992cf0361cd45bb9de00606e71a215858bfa66 linux-yocto/4.14: update to v4.14.24 f73dcd454e860623873821d3a41f92d1553fa3b0 linux-yocto/4.15: update to v4.15.7 240c3db54d426d901b5b4c63ce36d1da68f2080f linux-libc-headers: update to 4.15.7 be2982a630dbbfce6806750efe95720426980c69 systemd: Explicitly add hidden attribute to __start_BUS_ERROR_MAP and __stop_BUS_ERROR_MAP ba9d8c5a39ff1ac4ab083f93d721cda2087c6650 buildhistory: remove duplicate renames 551cb1f373417606c4fa6890eda469dec690d105 libcgroup: Various fixes f1318b0421a4b8da0c08044cdce826de5f5a8cb7 util-linux: Remove kill from native install 8715b5f3119d00f0b7c1d2025af6c56e9b45e2a2 libpng: Upgrade 1.6.32 -> 1.6.34 e5969c7ec781ddf5a70acee3adfaa2c1229e944c patch:2.7.5 -> 2.7.6 6c99444c767ac03b75f82d4b842be6bb6692454d iptables: 1.6.1 -> 1.6.2 3c198a52badac5ad78309814819000eddaed575d libdrm: 2.4.90 -> 2.4.91 12cb35e4da19fb5484a711c6d12336e674ecc0d2 libsolv: update to version 0.6.33 1260b3f25964c356afcac8870c9ebccd23f49c60 libunistring: update version to 0.9.9 3a7f48ebcbf201b1a22fa97804673e559701f321 flex: create separate package for libfl
Reading the logs carefully, one in particular stands out:
commit a7c9bc7020ab4c62fa60eb23257f07734b2582b0
Author: Bruce Ashfield <bruce.ashfield@windriver.com>
Date: Tue Mar 6 13:11:15 2018 -0500
linux-yocto: aufs and systemtap
Integrating a configuration change for systemtap:
features/systemtap/systemtap.cfg: enable CONFIG_KERNEL_DEBUG
A debugging kernel is going to be huge, which is why it look a lot longer to package and why the deploy directory size grew so much. After a quick discussion on the list, this was reverted.
