Live Session - Increased memory usage with preinstalled snap (fails to start with - gnome-session timeout)

[Jean-Baptiste Lallement]

Ubuntu Desktop Bionic 20180219 on VM

The session fails to start. There is the following message in the journal:

Feb 19 16:01:54 ubuntu gnome-session[1469]: gnome-session-binary[1469]: WARNING: Application 'org.gnome.Shell.desktop' failed to register before timeout
Feb 19 16:01:54 ubuntu gnome-session-binary[1469]: WARNING: Application 'org.gnome.Shell.desktop' failed to register before timeout
Feb 19 16:01:54 ubuntu gnome-session-binary[1469]: Unrecoverable failure in required component org.gnome.Shell.desktop
Feb 19 16:01:54 ubuntu gnome-session[1469]: gnome-session-binary[1469]: CRITICAL: We failed, but the fail whale is dead. Sorry....
Feb 19 16:01:54 ubuntu gnome-session-binary[1469]: CRITICAL: We failed, but the fail whale is dead. Sorry....
Feb 19 16:01:54 ubuntu at-spi-bus-launcher[1582]: XIO: fatal IO error 11 (Resource temporarily unavailable) on X server ":0"
Feb 19 16:01:54 ubuntu at-spi-bus-launcher[1582]: after 21 requests (21 known processed) with 0 events remaining.

On hardware boot time is slow but there is no timeout.

ProblemType: Bug
DistroRelease: Ubuntu 18.04
Package: gnome-session (not installed)
ProcVersionSignature: Ubuntu 4.13.0-32.35-generic 4.13.13
Uname: Linux 4.13.0-32-generic x86_64
ApportVersion: 2.20.8-0ubuntu10
Architecture: amd64
CurrentDesktop: ubuntu:GNOME
Date: Mon Feb 19 17:04:42 2018
InstallationDate: Installed on 2013-09-03 (1629 days ago)
InstallationMedia: Ubuntu 13.10 "Saucy Salamander" - Alpha amd64 (20130902)
ProcEnviron:
 TERM=screen-256color
 PATH=(custom, no user)
 XDG_RUNTIME_DIR=<set>
 LANG=fr_FR.UTF-8
 SHELL=/bin/bash
SourcePackage: gnome-session
UpgradeStatus: Upgraded to bionic on 2018-01-26 (24 days ago)

[Jean-Baptiste Lallement (jibel)]

journal from the machine affected

[Jean-Baptiste Lallement (jibel)]

The diff of squashfs shows that it coincides with the seeding of snap packages

+squashfs-root/var/lib/snapd/seed
+squashfs-root/var/lib/snapd/seed/assertions
+squashfs-root/var/lib/snapd/seed/assertions/core_3887.assert
+squashfs-root/var/lib/snapd/seed/assertions/generic.account
+squashfs-root/var/lib/snapd/seed/assertions/generic.account-key
+squashfs-root/var/lib/snapd/seed/assertions/generic-classic.model
+squashfs-root/var/lib/snapd/seed/assertions/gnome-3-26-1604_27.assert
+squashfs-root/var/lib/snapd/seed/assertions/gnome-calculator_75.assert
+squashfs-root/var/lib/snapd/seed/seed.yaml
+squashfs-root/var/lib/snapd/seed/snaps
+squashfs-root/var/lib/snapd/seed/snaps/core_3887.snap
+squashfs-root/var/lib/snapd/seed/snaps/gnome-3-26-1604_27.snap
+squashfs-root/var/lib/snapd/seed/snaps/gnome-calculator_75.snap

[Jean-Baptiste Lallement (jibel)]

Increasing the memory of the guest to 2GB fixes the problem.

[Jean-Baptiste Lallement (jibel)]

I noticed that core 3887 is on the image while 4017 is published to stable, a theory is that the refresh to stable happens during boot and consumes lot of resources leading to memory starvation or timeouts.

[Iain Lane (laney)]

On Tue, Feb 20, 2018 at 02:31:10PM -0000, Jean-Baptiste Lallement wrote:
> I noticed that core 3887 is on the image while 4017 is published to
> stable, a theory is that the refresh to stable happens during boot and
> consumes lot of resources leading to memory starvation or timeouts.

I don't think so, since that has OnStartupSec=15m (and
RandomizedDelaySec=6h but that could turn out to be close to 0) it won't
fire for at least 15 minutes.

Are you able to reproduce yourself? I don't know the details but I
suppose that seeded snaps (/var/lib/snapd/seed.yaml) need to be unpacked
somehow during boot - maybe that's it? Perhaps systemd-analyze or the
journal can tell us - could those be attached to test runs so we can
inspect?

--
Iain Lane [ <email address hidden> ]
Debian Developer [ <email address hidden> ]
Ubuntu Developer [ <email address hidden> ]

[Jean-Baptiste Lallement (jibel)]

During boot there are these lines

[...]
Feb 20 15:57:36 ubuntu snapd[982]: 2018/02/20 15:57:36.281638 daemon.go:306: started snapd/2.29.4.2+18.04 (series 16; classic) ubuntu/18.04 (amd64) linux/4.13.0-32-generic.
[...]
Feb 20 15:59:26 ubuntu snapd[1557]: 2018/02/20 15:59:26.013619 daemon.go:306: started snapd/2.30 (series 16; classic) ubuntu/18.04 (amd64) linux/4.13.0-32-generic.
[...]
Feb 20 16:01:43 ubuntu gnome-shell[1356]: GNOME Shell started at Tue Feb 20 2018 16:00:15 GMT+0000 (UTC)
[...]

So apparently 2.29 starts, something happens (update or init of snapd?), then it restarts with 2.30, then gnome-shell starts.

The journal is already attached in comment #2

To reproduce, boot bionic in a VM.

[Iain Lane (laney)]

On Tue, Feb 20, 2018 at 09:32:49PM -0000, Jean-Baptiste Lallement wrote:
> The journal is already attached in comment #2

I think that's some filtered view which is trying to only show errors,
or something.

> To reproduce, boot bionic in a VM.

There's probably some more configuration I need to do to make the system
slow enough. Just booting a bionic ISO in a VM with 1024 MiB of memory
and 1 vCPU does not cause gnome-session to time out for me.

Cheers,

--
Iain Lane [ <email address hidden> ]
Debian Developer [ <email address hidden> ]
Ubuntu Developer [ <email address hidden> ]

[Jeremy Bícha (jbicha)]

> Increasing the memory of the guest to 2GB fixes the problem.

What was the memory originally?

[Jean-Baptiste Lallement (jibel)]

Originally it was 1GB. I think the increased memory usage is caused by snapd that unsquashes the snaps.
The other issue is that gnome-shell times out which may or may not be related to the extra delay imposed by snapd. This point must be verified.