Ubuntu
sbuild package

slow sbuild Debian package builds (schroot calls are slow)

Bug #1645363 reported by Benjamin Drung
8
This bug affects 1 person
Affects Status Importance Assigned to Milestone
sbuild (Ubuntu)
Incomplete
Undecided
Unassigned
systemd (Ubuntu)
Incomplete
Undecided
Unassigned

Bug Description

Since the upgrade to Ubuntu 16.10, building packages with sbuild takes much more time than previously. sbuild creates a schroot session for building Debian packages and calls sbuild --run-session several times. Entering the sessions takes norally 10 ms, but entering the session from sbuild takes several seconds now:

time schroot -d / -c $session --run-session -q -u root -p -- true
real 0m2.098s
user 0m0.008s
sys 0m0.000s

This causes a drastic build time increase for small packages. Example package build time on my affected Ubuntu workstation:

Build-Time: 9 s
Install-Time: 115 s
Package-Time: 195 s (= 00:03:15)

compared to the build bot running Debian stable (having a slower processor):

Build-Time: 9 s
Install-Time: 24 s
Package-Time: 41 s

/var/log/syslog shows many entries about starting and stopping D-Bus services:

Nov 28 16:27:34 konstrukt systemd[1]: Created slice User Slice of root.
Nov 28 16:27:34 konstrukt systemd[1]: Starting User Manager for UID 0...
Nov 28 16:27:34 konstrukt systemd[1]: Started Session 2 of user root.
Nov 28 16:27:34 konstrukt systemd[21965]: Reached target Timers.
Nov 28 16:27:34 konstrukt systemd[21965]: Starting D-Bus User Message Bus Socket.
Nov 28 16:27:34 konstrukt systemd[21965]: Reached target Paths.
Nov 28 16:27:34 konstrukt systemd[21965]: Listening on D-Bus User Message Bus Socket.
Nov 28 16:27:34 konstrukt systemd[21965]: Reached target Sockets.
Nov 28 16:27:34 konstrukt systemd[21965]: Reached target Basic System.
Nov 28 16:27:34 konstrukt systemd[21965]: Starting Run Click user-level hooks...
Nov 28 16:27:34 konstrukt systemd[21965]: Started D-Bus User Message Bus.
Nov 28 16:27:34 konstrukt content-hub-pee[22023]: Error parsing manifest for package 'com.ubuntu.gallery': com.ubuntu.gallery does not exist in any database for user root
Nov 28 16:27:34 konstrukt /usr/lib/snapd/snapd[1086]: daemon.go:174: DEBUG: uid=0;@ GET /v2/snaps/com.ubuntu.gallery 40.327µs 404
Nov 28 16:27:34 konstrukt content-hub-pee[22023]: Unable to get snap information for 'com.ubuntu.gallery': Status code is: 404
Nov 28 16:27:34 konstrukt dbus-daemon[22004]: Activating service name='ca.desrt.dconf'
Nov 28 16:27:34 konstrukt content-hub-pee[22023]: Error parsing manifest for package 'com.ubuntu.gallery': com.ubuntu.gallery does not exist in any database for user root
Nov 28 16:27:34 konstrukt /usr/lib/snapd/snapd[1086]: daemon.go:174: DEBUG: uid=0;@ GET /v2/snaps/com.ubuntu.gallery 23.455µs 404
Nov 28 16:27:34 konstrukt content-hub-pee[22023]: Unable to get snap information for 'com.ubuntu.gallery': Status code is: 404
Nov 28 16:27:34 konstrukt dbus-daemon[22004]: Successfully activated service 'ca.desrt.dconf'
Nov 28 16:27:35 konstrukt dbus-daemon[22004]: Activating via systemd: service name='org.gtk.vfs.Daemon' unit='gvfs-daemon.service'
Nov 28 16:27:35 konstrukt systemd[21965]: Starting Virtual filesystem service...
Nov 28 16:27:35 konstrukt dbus-daemon[22004]: Successfully activated service 'org.gtk.vfs.Daemon'
Nov 28 16:27:35 konstrukt systemd[21965]: Started Virtual filesystem service.
Nov 28 16:27:35 konstrukt click[21997]: /usr/lib/ubuntu-push-client/click-hook:15: PyGIWarning: Click was imported without specifying a version first. Use gi.require_version('Click', '0.4') before import to ensure that the right version gets loaded.
Nov 28 16:27:35 konstrukt click[21997]: from gi.repository import Click
Nov 28 16:27:35 konstrukt click[21997]: hooks.vala:1216: User-level hook push-helper failed: Hook command '/usr/lib/ubuntu-push-client/click-hook-wrapper' failed: Child process exited with code 1
Nov 28 16:27:35 konstrukt click[21997]: Some user-level hooks failed: push-helper
Nov 28 16:27:35 konstrukt systemd[21965]: click-user-hooks.service: Main process exited, code=exited, status=1/FAILURE
Nov 28 16:27:35 konstrukt systemd[21965]: Failed to start Run Click user-level hooks.
Nov 28 16:27:35 konstrukt systemd[21965]: click-user-hooks.service: Unit entered failed state.
Nov 28 16:27:35 konstrukt systemd[21965]: click-user-hooks.service: Failed with result 'exit-code'.
Nov 28 16:27:35 konstrukt systemd[21965]: Reached target Default.
Nov 28 16:27:35 konstrukt systemd[21965]: Startup finished in 497ms.
Nov 28 16:27:35 konstrukt systemd[1]: Started User Manager for UID 0.
Nov 28 16:27:35 konstrukt schroot[22084]: [pb-jessie-93c04c41-79af-4e32-addb-09a186998122 chroot] (bdrung->root) Running command: "getent group sbuild"
Nov 28 16:27:35 konstrukt systemd[1]: Stopping User Manager for UID 0...
Nov 28 16:27:35 konstrukt systemd[21965]: Stopping D-Bus User Message Bus...
Nov 28 16:27:35 konstrukt systemd[21965]: Stopped target Default.
Nov 28 16:27:35 konstrukt systemd[21965]: Stopping Virtual filesystem service...
Nov 28 16:27:35 konstrukt systemd[21965]: Stopped D-Bus User Message Bus.
Nov 28 16:27:35 konstrukt systemd[1]: Started Session 2 of user root.
Nov 28 16:27:36 konstrukt systemd[21965]: Stopped Virtual filesystem service.
Nov 28 16:27:36 konstrukt systemd[21965]: Stopped target Basic System.
Nov 28 16:27:36 konstrukt systemd[21965]: Stopped target Sockets.
Nov 28 16:27:36 konstrukt systemd[21965]: Closed D-Bus User Message Bus Socket.
Nov 28 16:27:36 konstrukt systemd[21965]: Reached target Shutdown.
Nov 28 16:27:36 konstrukt systemd[21965]: Starting Exit the Session...
Nov 28 16:27:36 konstrukt systemd[21965]: Stopped target Timers.
Nov 28 16:27:36 konstrukt systemd[21965]: Stopped target Paths.
Nov 28 16:27:36 konstrukt systemd[21965]: Received SIGRTMIN+24 from PID 22105 (kill).
Nov 28 16:27:36 konstrukt systemd[1]: Starting User Manager for UID 0...
Nov 28 16:27:36 konstrukt systemd[22108]: Reached target Paths.
Nov 28 16:27:36 konstrukt systemd[22108]: Reached target Timers.
Nov 28 16:27:36 konstrukt systemd[22108]: Starting D-Bus User Message Bus Socket.
Nov 28 16:27:36 konstrukt systemd[22108]: Listening on D-Bus User Message Bus Socket.
Nov 28 16:27:36 konstrukt systemd[22108]: Reached target Sockets.
Nov 28 16:27:36 konstrukt systemd[22108]: Reached target Basic System.
Nov 28 16:27:36 konstrukt systemd[22108]: Starting Run Click user-level hooks...
Nov 28 16:27:36 konstrukt systemd[22108]: Started D-Bus User Message Bus.
[...]

ProblemType: Bug
DistroRelease: Ubuntu 16.10
Package: sbuild 0.71.0-2ubuntu1
ProcVersionSignature: Ubuntu 4.8.0-27.29-generic 4.8.1
Uname: Linux 4.8.0-27-generic x86_64
ApportVersion: 2.20.3-0ubuntu8
Architecture: amd64
CurrentDesktop: Unity
Date: Mon Nov 28 16:28:44 2016
PackageArchitecture: all
SourcePackage: sbuild
UpgradeStatus: Upgraded to yakkety on 2016-11-15 (13 days ago)

Revision history for this message
Benjamin Drung (bdrung) wrote :
Revision history for this message
Martin Pitt (pitti) wrote :

At least for me the reason was bug 1626436. Can you try the test kernel there and see if that helps?

Changed in systemd (Ubuntu):
status: New → Incomplete
Changed in sbuild (Ubuntu):
status: New → Incomplete
Revision history for this message
Benjamin Drung (bdrung) wrote :

Yes! With linux 4.8.0-29-generic #31~lp1626436ProposedWithTwoPatches the build is fast again:

Build-Time: 5
Install-Time: 18
Package-Time: 36

Revision history for this message
Martin Pitt (pitti) wrote :

Thanks for confirming!

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.