[Bug 1645363] Re: slow sbuild Debian package builds (schroot calls are slow)

Mon Nov 28 16:16:17 UTC 2016

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

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

-- 
You received this bug notification because you are a member of Ubuntu
Foundations Bugs, which is subscribed to systemd in Ubuntu.
https://bugs.launchpad.net/bugs/1645363

Title:
  slow sbuild Debian package builds (schroot calls are slow)

Status in sbuild package in Ubuntu:
  Incomplete
Status in systemd package in Ubuntu:
  Incomplete

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)

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/sbuild/+bug/1645363/+subscriptions