7339 2015-02-20 13:02:33 +0000 Performance issue in do_rootfs (buildhistory_list_installed_image) 2016-04-06 01:59:18 +0000 1 1 7 Build System, Metadata & Runtime OE-Core core 1.7 x86 Multiple RESOLVED FIXED Medium enhancement 2.1 1 richard.purdie bluelightning Martin.Jansa meta.mr.watcher meta.watcher --- --- No (bug/feature does not impact docs) oldest_to_newest 48949 0 richard.purdie 2015-02-20 13:02:33 +0000 Applying a patch like: diff --git a/meta/lib/oe/utils.py b/meta/lib/oe/utils.py index 1f84ba4..33110c6 100644 --- a/meta/lib/oe/utils.py +++ b/meta/lib/oe/utils.py @@ -149,8 +149,10 @@ def execute_pre_post_process(d, cmds): for cmd in cmds.strip().split(';'): cmd = cmd.strip() if cmd != '': + bb.warn("Executing %s ..." % cmd) bb.note("Executing %s ..." % cmd) bb.build.exec_func(cmd, d) + bb.warn("Finished Executing %s ..." % cmd) def multiprocess_exec(commands, function): import signal and then with a script predate.sh: $ cat predate.sh #!/bin/bash while read line ; do echo "$(date): ${line}" done and a command like: MACHINE=qemux86-64 time bitbake core-image-sato-sdk -c rootfs -f -P | ./predate.sh we see: richard@dax:/media/build1/poky/build$ MACHINE=qemux86-64 time bitbake core-image-sato-sdk -c rootfs -f -P | ./predate.sh Thu Feb 19 18:04:26 UTC 2015: NOTE: Started PRServer with DBfile: /media/build1/poky/build/cache/prserv.sqlite3, IP: 127.0.0.1, PORT: 39996, PID: 22797 Thu Feb 19 18:04:26 UTC 2015: Loading cache...done. Thu Feb 19 18:04:26 UTC 2015: Loaded 1551 entries from dependency cache. Thu Feb 19 18:04:27 UTC 2015: NOTE: Resolving any missing task queue dependencies Thu Feb 19 18:04:33 UTC 2015: Thu Feb 19 18:04:33 UTC 2015: Build Configuration: Thu Feb 19 18:04:33 UTC 2015: BB_VERSION = "1.25.0" Thu Feb 19 18:04:33 UTC 2015: BUILD_SYS = "x86_64-linux" Thu Feb 19 18:04:33 UTC 2015: NATIVELSBSTRING = "Ubuntu-14.10" Thu Feb 19 18:04:33 UTC 2015: TARGET_SYS = "x86_64-poky-linux" Thu Feb 19 18:04:33 UTC 2015: MACHINE = "qemux86-64" Thu Feb 19 18:04:33 UTC 2015: DISTRO = "poky" Thu Feb 19 18:04:33 UTC 2015: DISTRO_VERSION = "1.7" Thu Feb 19 18:04:33 UTC 2015: TUNE_FEATURES = "m64 core2" Thu Feb 19 18:04:33 UTC 2015: TARGET_FPU = "" Thu Feb 19 18:04:33 UTC 2015: meta = "master-next:2f926c3fe7bf05ae1ae1f753164c6d9faad1f119" Thu Feb 19 18:04:33 UTC 2015: meta-ti = "master:b20619dacb5c0995a1cc8ae6578433154970a624" Thu Feb 19 18:04:33 UTC 2015: meta-yocto Thu Feb 19 18:04:33 UTC 2015: meta-yocto-bsp = "master-next:2f926c3fe7bf05ae1ae1f753164c6d9faad1f119" Thu Feb 19 18:04:33 UTC 2015: meta-qt3 = "master:4772424ab69908d4e3b9d6d4717ca889468e6acd" Thu Feb 19 18:04:33 UTC 2015: meta-intel = "master:a3a380373b3f47df90f0c585ce9b071f80b216c9" Thu Feb 19 18:04:33 UTC 2015: meta-minnow = "master:13a5f2ab84c7284647a3e067a33109c11dae0568" Thu Feb 19 18:04:33 UTC 2015: meta-baremetal = "master-next:2f926c3fe7bf05ae1ae1f753164c6d9faad1f119" Thu Feb 19 18:04:33 UTC 2015: meta-emenlow = "master:a3a380373b3f47df90f0c585ce9b071f80b216c9" Thu Feb 19 18:04:33 UTC 2015: meta-fsl-arm = "master:a47c9aa59280035667d2240775f94fd07b513db7" Thu Feb 19 18:04:33 UTC 2015: meta-fsl-ppc = "master:deb326df1489d4844f911605a2627f95c89b167f" Thu Feb 19 18:04:33 UTC 2015: Thu Feb 19 18:04:33 UTC 2015: NOTE: Preparing RunQueue Thu Feb 19 18:04:39 UTC 2015: NOTE: Tainting hash to force rebuild of task /media/build1/poky/meta/recipes-sato/images/core-image-sato-sdk.bb, do_rootfs Thu Feb 19 18:04:40 UTC 2015: WARNING: /media/build1/poky/meta/recipes-sato/images/core-image-sato-sdk.bb.do_rootfs is tainted from a forced run Thu Feb 19 18:04:44 UTC 2015: NOTE: Executing SetScene Tasks Thu Feb 19 18:04:44 UTC 2015: NOTE: Executing RunQueue Tasks Thu Feb 19 18:04:47 UTC 2015: NOTE: Running task 4651 of 4651 (ID: 6, /media/build1/poky/meta/recipes-sato/images/core-image-sato-sdk.bb, do_rootfs) Thu Feb 19 18:04:49 UTC 2015: NOTE: recipe core-image-sato-sdk-1.0-r0: task do_rootfs: Started Thu Feb 19 18:08:53 UTC 2015: WARNING: Executing write_package_manifest ... Thu Feb 19 18:08:53 UTC 2015: WARNING: Finished Executing write_package_manifest ... Thu Feb 19 18:08:53 UTC 2015: WARNING: Executing license_create_manifest ... Thu Feb 19 18:10:04 UTC 2015: WARNING: Finished Executing license_create_manifest ... Thu Feb 19 18:10:04 UTC 2015: WARNING: Executing ssh_allow_empty_password ... Thu Feb 19 18:10:04 UTC 2015: WARNING: Finished Executing ssh_allow_empty_password ... Thu Feb 19 18:10:04 UTC 2015: WARNING: Executing postinst_enable_logging ... Thu Feb 19 18:10:04 UTC 2015: WARNING: Finished Executing postinst_enable_logging ... Thu Feb 19 18:10:04 UTC 2015: WARNING: Executing rootfs_update_timestamp ... Thu Feb 19 18:10:04 UTC 2015: WARNING: Finished Executing rootfs_update_timestamp ... Thu Feb 19 18:10:04 UTC 2015: WARNING: Executing ssh_disable_dns_lookup ... Thu Feb 19 18:10:04 UTC 2015: WARNING: Finished Executing ssh_disable_dns_lookup ... Thu Feb 19 18:10:04 UTC 2015: WARNING: None Thu Feb 19 18:10:04 UTC 2015: WARNING: Executing write_image_manifest ... Thu Feb 19 18:10:04 UTC 2015: WARNING: Finished Executing write_image_manifest ... Thu Feb 19 18:10:04 UTC 2015: WARNING: Executing buildhistory_list_installed_image ... Thu Feb 19 18:10:06 UTC 2015: WARNING: Finished Executing buildhistory_list_installed_image ... Thu Feb 19 18:10:06 UTC 2015: WARNING: Executing buildhistory_get_image_installed ... Thu Feb 19 18:12:10 UTC 2015: WARNING: Finished Executing buildhistory_get_image_installed ... Thu Feb 19 18:12:10 UTC 2015: WARNING: Executing mklibs_optimize_image ... Thu Feb 19 18:12:10 UTC 2015: WARNING: Finished Executing mklibs_optimize_image ... Thu Feb 19 18:12:10 UTC 2015: WARNING: Executing prelink_image ... Thu Feb 19 18:12:19 UTC 2015: WARNING: Finished Executing prelink_image ... Thu Feb 19 18:21:43 UTC 2015: WARNING: Executing buildhistory_get_imageinfo ... Thu Feb 19 18:21:57 UTC 2015: WARNING: Finished Executing buildhistory_get_imageinfo ... Thu Feb 19 18:22:01 UTC 2015: NOTE: recipe core-image-sato-sdk-1.0-r0: task do_rootfs: Succeeded Thu Feb 19 18:22:01 UTC 2015: NOTE: Tasks Summary: Attempted 4651 tasks of which 4650 didn't need to be rerun and all succeeded. Thu Feb 19 18:22:01 UTC 2015: NOTE: Writing buildhistory Thu Feb 19 18:22:03 UTC 2015: Thu Feb 19 18:22:03 UTC 2015: Summary: There were 26 WARNING messages shown. Thu Feb 19 18:22:03 UTC 2015: Raw profiling information saved to profile.log and processed statistics to profile.log.processed 1033.12user 191.91system 17:39.03elapsed 115%CPU (0avgtext+0avgdata 316992maxresident)k 32inputs+14322104outputs (13major+15646646minor)pagefaults 0swaps Of the 17 minute build 2 minutes are spent in buildhistory_list_installed_image, specifically in the package size generation code and the loops around oe-pkgdata-util. I believe we can optimise this. With that code commented out, the rest of the function takes 4 seconds. 60833 1 bluelightning 2016-04-06 01:59:18 +0000 Fix merged to master: http://git.yoctoproject.org/cgit/cgit.cgi/poky/commit/?id=4d364f27e76cba86155c29719710215249a231f0