Bug 7339 - Performance issue in do_rootfs (buildhistory_list_installed_image)
Summary: Performance issue in do_rootfs (buildhistory_list_installed_image)
Status: RESOLVED FIXED
Alias: None
Product: OE-Core
Classification: Build System, Metadata & Runtime
Component: core (show other bugs)
Version: 1.7
Hardware: x86 Multiple
: Medium enhancement
Target Milestone: 2.1
Assignee: Paul Eggleton
QA Contact:
URL:
Whiteboard:
Depends on:
Blocks:
 
Reported: 2015-02-20 13:02 UTC by Richard Purdie
Modified: 2016-04-06 01:59 UTC (History)
3 users (show)

See Also:
OS type for building Yocto: ---
Type of Regression: ---
Verified:
Documentation change: No (bug/feature does not impact docs)


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Richard Purdie 2015-02-20 13:02:33 UTC
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.