Speed up `bst build` command (particularly when workspaces are in use)
When performing a small, incremental build of a project using a BuildStream workspace, executing the bst build command outside a bst shell is dramatically slower than it would be to perform the build inside bst shell environment. To test, I first performed a full build of WebKit using the command bst build core-deps/WebKit.bst, then added a comment to an arbitrary .cpp file and ran the same command again. The output:
$ time bst build core-deps/WebKit.bst
[--:--:--][][] START Loading pipeline
[00:00:00][][] SUCCESS Loading pipeline
[--:--:--][][] START Resolving pipeline
[00:00:00][][] SUCCESS Resolving pipeline
[--:--:--][][] START Initializing remote caches
[00:00:02][][] SUCCESS Initializing remote caches
[--:--:--][][] START Resolving cached state
[00:01:26][][] SUCCESS Resolving cached state
BuildStream Version 1.1.1
Session Start: Saturday, 10-03-2018 at 13:31:14
Project: gnome (/home/mcatanzaro/Projects/gnome-build-meta)
Targets: core-deps/WebKit.bst
User Configuration
Configuration File: /home/mcatanzaro/.config/buildstream.conf
Log Files: /home/mcatanzaro/.cache/buildstream/logs
Source Mirrors: /home/mcatanzaro/.cache/buildstream/sources
Build Area: /home/mcatanzaro/.cache/buildstream/build
Artifact Cache: /home/mcatanzaro/.cache/buildstream/artifacts
Maximum Fetch Tasks: 10
Maximum Build Tasks: 4
Maximum Push Tasks: 4
Maximum Network Retries: 2
Project Options
arch: x86_64
Pipeline
cached ab45dd87 base/base-system.bst
cached 6db93431 base/base-configure.bst
cached 12ab0a93 base/linker-priority.bst
cached 593e35e8 base.bst
cached 96b1588a core-deps/yelp-xsl.bst
cached cc2163c5 core-deps/yelp-tools.bst
cached 9f348f1d core-deps/gtk-doc.bst
cached ec9dc658 core-deps/glib.bst
cached 038f7215 core-deps/gobject-introspection.bst
cached 86c21b65 core-deps/meson.bst
cached 4004853b core-deps/at-spi2-core.bst
cached ef47478d core-deps/brotli.bst
cached 2c272ae3 core-deps/libgudev.bst
cached 1d79f78d core-deps/libmbim.bst
cached 9955919b core-deps/libqmi.bst
cached 61efd6e5 core-deps/ModemManager.bst
cached 216b47df core-deps/json-glib.bst
cached 181326b4 core-deps/m4-common.bst
cached e5196ebe core-deps/vala.bst
cached 8185e258 core-deps/libsoup.bst
cached 4ab5b7f1 core-deps/geoclue.bst
cached 1ed7e436 core-deps/harfbuzz.bst
cached 359941bd core-deps/pango.bst
cached 98e6888d core-deps/wayland.bst
cached 517cffbc core-deps/atk.bst
cached 2407e07e core-deps/at-spi2-atk.bst
cached 81d1654d core-deps/gdk-pixbuf.bst
cached ac060fce core-deps/wayland-protocols.bst
cached 0566cf06 core-deps/gtk+-3.bst
cached ef29eb55 core-deps/gstreamer.bst
cached 3fd21830 core-deps/iso-codes.bst
cached 2e40a365 core-deps/gst-plugins-base.bst
cached b082219d core-deps/gst-libav.bst
cached ee290959 core-deps/graphene.bst
cached 8f3895db core-deps/gst-plugins-bad.bst
cached 74a40cc6 core-deps/gst-plugins-good.bst
cached 4c2e7227 core-deps/gnome-common.bst
cached e3a95864 core-deps/libnotify.bst
cached 91cb7ec6 core-deps/libsecret.bst
cached e707f814 core-deps/woff2.bst
buildable ???????? core-deps/WebKit.bst Workspaces: ~/Projects/WebKit
[--:--:--][][] WARNING Unused workspaces
core/epiphany.bst
core/glib-networking.bst
[--:--:--][][] START Checking sources
[00:00:00][][] SUCCESS Checking sources
[--:--:--][][] START Starting build
[--:--:--][????????][build:core-deps/WebKit.bst ] START home/mcatanzaro/.cache/buildstream/logs/gnome/core-deps-WebKit/????????-build.9516.log
[--:--:--][????????][build:core-deps/WebKit.bst ] START Staging dependencies
[--:--:--][????????][build:core-deps/WebKit.bst ] WARNING Non-whitelisted overlaps detected
Staged files overwrite existing files in staging area:
/usr/bin/gtkdoc-check: core-deps/gtk-doc.bst is not permitted to overlap other elements, order core-deps/gtk-doc.bst above base/base-configure.bst
/usr/bin/gtkdoc-depscan: core-deps/gtk-doc.bst is not permitted to overlap other elements, order core-deps/gtk-doc.bst above base/base-configure.bst
/usr/bin/gtkdoc-fixxref: core-deps/gtk-doc.bst is not permitted to overlap other elements, order core-deps/gtk-doc.bst above base/base-configure.bst
/usr/bin/gtkdoc-mkdb: core-deps/gtk-doc.bst is not permitted to overlap other elements, order core-deps/gtk-doc.bst above base/base-configure.bst
/usr/bin/gtkdoc-mkhtml: core-deps/gtk-doc.bst is not permitted to overlap other elements, order core-deps/gtk-doc.bst above base/base-configure.bst
/usr/bin/gtkdoc-mkman: core-deps/gtk-doc.bst is not permitted to overlap other elements, order core-deps/gtk-doc.bst above base/base-configure.bst
/usr/bin/gtkdoc-mkpdf: core-deps/gtk-doc.bst is not permitted to overlap other elements, order core-deps/gtk-doc.bst above base/base-configure.bst
/usr/bin/gtkdoc-rebase: core-deps/gtk-doc.bst is not permitted to overlap other elements, order core-deps/gtk-doc.bst above base/base-configure.bst
/usr/bin/gtkdoc-scan: core-deps/gtk-doc.bst is not permitted to overlap other elements, order core-deps/gtk-doc.bst above base/base-configure.bst
/usr/bin/gtkdoc-scangobj: core-deps/gtk-doc.bst is not permitted to overlap other elements, order core-deps/gtk-doc.bst above base/base-configure.bst
/usr/bin/gtkdocize: core-deps/gtk-doc.bst is not permitted to overlap other elements, order core-deps/gtk-doc.bst above base/base-configure.bst
/usr/lib/cmake/GtkDoc/GtkDocConfig.cmake: core-deps/gtk-doc.bst is not permitted to overlap other elements, order core-deps/gtk-doc.bst above base/base-configure.bst
/usr/lib/cmake/GtkDoc/GtkDocConfigVersion.cmake: core-deps/gtk-doc.bst is not permitted to overlap other elements, order core-deps/gtk-doc.bst above base/base-configure.bst
/usr/lib/cmake/GtkDoc/GtkDocScanGObjWrapper.cmake: core-deps/gtk-doc.bst is not permitted to overlap other elements, order core-deps/gtk-doc.bst above base/base-configure.bst
/usr/share/aclocal/gtk-doc.m4: core-deps/gtk-doc.bst is not permitted to overlap other elements, order core-deps/gtk-doc.bst above base/base-configure.bst
/usr/share/gtk-doc/data/devhelp2.xsd: core-deps/gtk-doc.bst is not permitted to overlap other elements, order core-deps/gtk-doc.bst above base/base-configure.bst
/usr/share/gtk-doc/data/devhelp2.xsl: core-deps/gtk-doc.bst is not permitted to overlap other elements, order core-deps/gtk-doc.bst above base/base-configure.bst
/usr/share/gtk-doc/data/gtk-doc.flat.make: core-deps/gtk-doc.bst is not permitted to overlap other elements, order core-deps/gtk-doc.bst above base/base-configure.bst
/usr/share/gtk-doc/data/gtk-doc.make: core-deps/gtk-doc.bst is not permitted to overlap other elements, order core-deps/gtk-doc.bst above base/base-configure.bst
Message contains 1223 additional lines
[00:00:06][????????][build:core-deps/WebKit.bst ] SUCCESS Staging dependencies
[--:--:--][????????][build:core-deps/WebKit.bst ] START Integrating sandbox
[--:--:--][????????][build:core-deps/WebKit.bst ] STATUS Running integration command
ldconfig
[--:--:--][????????][build:core-deps/WebKit.bst ] STATUS Running integration command
PKGSYSTEM_ENABLE_FSYNC=0 update-mime-database /usr/share/mime
[--:--:--][????????][build:core-deps/WebKit.bst ] STATUS Running integration command
update-desktop-database -v
[--:--:--][????????][build:core-deps/WebKit.bst ] STATUS Running integration command
glib-compile-schemas /usr/share/glib-2.0/schemas
[--:--:--][????????][build:core-deps/WebKit.bst ] STATUS Running integration command
gdk-pixbuf-query-loaders --update-cache
[--:--:--][????????][build:core-deps/WebKit.bst ] STATUS Running integration command
for dir in /usr/share/icons/*; do
if test -f $dir/index.theme; then
gtk-update-icon-cache --quiet $dir
fi
done
[--:--:--][????????][build:core-deps/WebKit.bst ] STATUS Running integration command
gtk-query-immodules-3.0 --update-cache
[00:00:14][????????][build:core-deps/WebKit.bst ] SUCCESS Integrating sandbox
[--:--:--][????????][build:core-deps/WebKit.bst ] START Staging sources
[00:00:00][????????][build:core-deps/WebKit.bst ] SUCCESS Staging sources
[--:--:--][????????][build:core-deps/WebKit.bst ] START Running configure-commands
[--:--:--][????????][build:core-deps/WebKit.bst ] STATUS Running configure-commands
cmake -B_builddir -H. -DCMAKE_INSTALL_PREFIX:PATH="/usr" \
-DCMAKE_INSTALL_LIBDIR=lib -DCMAKE_BUILD_TYPE=RelWithDebInfo -DPORT=GTK -DENABLE_PLUGIN_PROCESS_GTK2=OFF
[00:00:04][????????][build:core-deps/WebKit.bst ] SUCCESS Running configure-commands
[--:--:--][????????][build:core-deps/WebKit.bst ] START Running build-commands
[--:--:--][????????][build:core-deps/WebKit.bst ] STATUS Running build-commands
make -C _builddir
[00:01:30][????????][build:core-deps/WebKit.bst ] SUCCESS Running build-commands
[--:--:--][????????][build:core-deps/WebKit.bst ] START Running install-commands
[--:--:--][????????][build:core-deps/WebKit.bst ] STATUS Running install-commands
make -j1 -C _builddir DESTDIR="/buildstream/install" install
[00:00:15][????????][build:core-deps/WebKit.bst ] SUCCESS Running install-commands
[--:--:--][????????][build:core-deps/WebKit.bst ] START Running strip-commands
[--:--:--][????????][build:core-deps/WebKit.bst ] STATUS Running strip-commands
find "/buildstream/install" -type f \
'(' -perm -111 -o -name '*.so*' \
-o -name '*.cmxs' -o -name '*.node' ')' \
-exec sh -ec \
'read -n4 hdr <"$1" # check for elf header
if [ "$hdr" != "$(printf \\x7fELF)" ]; then
exit 0
fi
debugfile="/buildstream/install/usr/lib/debug/$(basename "$1")"
mkdir -p "$(dirname "$debugfile")"
objcopy --only-keep-debug --compress-debug-sections "$1" "$debugfile"
chmod 644 "$debugfile"
strip --remove-section=.comment --remove-section=.note --strip-unneeded "$1"
objcopy --add-gnu-debuglink "$debugfile" "$1"' - {} ';'
[00:00:00][????????][build:core-deps/WebKit.bst ] SUCCESS Running strip-commands
[--:--:--][????????][build:core-deps/WebKit.bst ] START Caching Artifact
[00:00:07][????????][build:core-deps/WebKit.bst ] SUCCESS Caching Artifact
[00:04:03][????????][build:core-deps/WebKit.bst ] SUCCESS home/mcatanzaro/.cache/buildstream/logs/gnome/core-deps-WebKit/????????-build.9516.log
[00:05:34][][] SUCCESS Build Complete
Pipeline Summary
Total: 41
Session: 1
Pull Queue: processed 0, skipped 1, failed 0
Fetch Queue: processed 0, skipped 1, failed 0
Build Queue: processed 1, skipped 0, failed 0
real 7m4.588s
user 3m3.041s
sys 0m40.788sThat's seven minutes for a rebuild that touched only one single file. When using JHBuild, this would take half a minute or so at most. Note the timings:
- 6s to stage dependencies
- 14s integrating sandbox
- 4s running configure commands
- 1m30s running build commands
- 15s running install commands
- 4m3s caching artifact
I suspect the 1m30s spent running build commands could be cut down dramatically by fixing #279 (closed). As it stands, performing a make -j8 inside the shell environment takes 59s, so 1m30s is not unreasonable.
Looks like the vast majority of the time is spend caching the build artifact. Is this even useful, since a workspace is in use? Maybe it should be skipped for elements that have an open workspace? Is there any potential to speed it up?
Lastly, notice that BuildStream reports that it took 5m34s to do all of this, but it really took 7m5s total. That's a huge difference, so I guess something is wrong with BuildStream's accounting of time.
Edited by Michael Catanzaro