I’ve had this problem since 19.04 or 19.10 and thought it’d at some point fix itself with system updates, since I thought it was just a bug. Now I am on 20.04 and this problem still persists. Apps such as mumble or spotify take 8-10 seconds to start. When still had the non-snap versions of these, they started much faster. I didn’t really find any solution for this online and don’t know how to debug these problems.
Actually I just installed spotify and ran this myself, it seems that spotify is in the same boat as chromium, in that there is a lot of decompression that needs to happen for the spotify snap to launch. If I use etrace on my machine I see a total of 8.18 seconds with tracing turned on and 7.17 seconds with tracing turned off, but if I recompress the snap to use lzo, I see 5.09 seconds with tracing turned on and 3.57s with tracing turned off.
So, I just ran this for “mumble”. It appears Jack is part of the problem. The first 5 seconds are pretty much spent messing with Jack (Further down below is the spotify output):
~$ etrace exec --use-snap-run --discard-snap-ns mumble
2020/06/15 18:41:32 xdotool.go:84:
connect(2) call to /dev/shm/jack-1000/default/jack_0 failed (err=No such file or directory)
exec of JACK server (command = "/usr/bin/jackd") failed: No such file or directory
connect(2) call to /dev/shm/jack-1000/default/jack_0 failed (err=No such file or directory)
connect(2) call to /dev/shm/jack-1000/default/jack_0 failed (err=No such file or directory)
connect(2) call to /dev/shm/jack-1000/default/jack_0 failed (err=No such file or directory)
connect(2) call to /dev/shm/jack-1000/default/jack_0 failed (err=No such file or directory)
connect(2) call to /dev/shm/jack-1000/default/jack_0 failed (err=No such file or directory)
attempt to connect to server failed
<W>2020-06-15 18:41:38.891 JackAudioSystem: unable to open client due to 2 errors:
<W>2020-06-15 18:41:38.892 JackAudioSystem: JackFailure - overall operation failed
<W>2020-06-15 18:41:38.892 JackAudioSystem: JackServerFailed - unable to connect to the JACK server
<W>2020-06-15 18:41:39.911 G15LCDEngineUnix: Unable to connect to G15Daemon.
<D>2020-06-15 18:41:39.913 libopus 1.2.1 from /snap/mumble/1141/bin/libopus.so.0
<W>2020-06-15 18:41:39.916 CELT bitstream 8000000b from /snap/mumble/1141/bin/libcelt0.so.0.7.0
<W>2020-06-15 18:41:39.917 CELT bitstream 80000010 from /snap/mumble/1141/bin/libcelt0.so.0.11.0
<W>2020-06-15 18:41:39.921 Theme: "Mumble"
<W>2020-06-15 18:41:39.921 Style: "Dark"
<W>2020-06-15 18:41:39.922 --> qss: ":themes/Mumble/Dark.qss"
<W>2020-06-15 18:41:39.923 Locale is "en_GB" (System: "en_GB")
<W>2020-06-15 18:41:39.959 propsReply "An AppArmor policy prevents this sender from sending this message to this recipient; type=\"method_call\", sender=\":1.98\" (uid=1000 pid=4456 comm=\"/snap/mumble/1141/bin/mumble \" label=\"snap.mumble.mumble (enforce)\") interface=\"org.freedesktop.DBus.Properties\" member=\"GetAll\" error name=\"(unset)\" requested_reply=\"0\" destination=\"org.freedesktop.NetworkManager\" (uid=0 pid=929 comm=\"/usr/sbin/NetworkManager --no-daemon \" label=\"unconfined\")"
<W>2020-06-15 18:41:39.960 nmReply "An AppArmor policy prevents this sender from sending this message to this recipient; type=\"method_call\", sender=\":1.98\" (uid=1000 pid=4456 comm=\"/snap/mumble/1141/bin/mumble \" label=\"snap.mumble.mumble (enforce)\") interface=\"org.freedesktop.NetworkManager\" member=\"GetDevices\" error name=\"(unset)\" requested_reply=\"0\" destination=\"org.freedesktop.NetworkManager\" (uid=0 pid=929 comm=\"/usr/sbin/NetworkManager --no-daemon \" label=\"unconfined\")"
<W>2020-06-15 18:41:39.967 "Object path cannot be empty"
<W>2020-06-15 18:41:40.027 Database SQLite: "3.22.0"
<W>2020-06-15 18:41:40.030 Overlay: Listening on "/run/user/1000/snap.mumble/MumbleOverlayPipe"
<W>2020-06-15 18:41:40.035 Updating application palette
<W>2020-06-15 18:41:40.053 GlobalShortcutX: Using XI2 2.3
Mumble Link plugin: error creating shared memory
<W>2020-06-15 18:41:40.457 AudioInput: Opus encoder set for VOIP
<W>2020-06-15 18:41:40.457 AudioInput: 96000 bits/s, 48000 hz, 480 sample
<W>2020-06-15 18:41:40.457 PulseAudio: Starting input alsa_input.usb-SteelSeries_SteelSeries_Siberia_800-00.mono-fallback
<W>2020-06-15 18:41:40.457 PulseAudio: Starting output: alsa_output.usb-SteelSeries_SteelSeries_Siberia_800-00.analog-stereo
<W>2020-06-15 18:41:40.461 AudioOutput: Initialized 1 channel 44100 hz mixer
<W>2020-06-15 18:41:40.468 AudioInput: Initialized mixer for 1 channel 44100 hz mic and 0 channel 48000 hz echo
warning: The VAD has been replaced by a hack pending a complete rewrite
<W>2020-06-15 18:41:40.535 Database SQLite: "3.22.0"
<W>2020-06-15 18:41:40.535 OpenSSL Support: 1 (OpenSSL 1.1.1 11 Sep 2018)
<W>2020-06-15 18:41:40.618 ServerHandler: TLS cipher preference is "TLS_AES_256_GCM_SHA384:TLS_CHACHA20_POLY1305_SHA256:TLS_AES_128_GCM_SHA256:ECDHE-ECDSA-AES256-GCM-SHA384:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-RSA-AES128-GCM-SHA256:DHE-RSA-AES256-GCM-SHA384:DHE-RSA-AES128-GCM-SHA256:DHE-RSA-AES256-SHA:DHE-RSA-AES128-SHA:AES256-SHA:AES128-SHA"
<W>2020-06-15 18:41:40.702 OSInfo: Failed to execute lsb_release
<W>2020-06-15 18:41:40.711 TextToSpeech: Failed to contact speech dispatcher.
<W>2020-06-15 18:41:42.869 PulseAudio: Forcibly disconnected from PulseAudio
50 exec calls during snap run:
Start Stop Elapsed Exec
0 175022 175.02284ms /usr/bin/snap
12426 21911 9.485006ms /sbin/apparmor_parser
37679 42958 5.279064ms /snap/core/9289/usr/lib/snapd/snap-seccomp
51333 52506 1.173019ms /usr/lib/snapd/snap-device-helper
53202 54481 1.279115ms /usr/lib/snapd/snap-device-helper
55489 56597 1.108884ms /usr/lib/snapd/snap-device-helper
57446 58671 1.225948ms /usr/lib/snapd/snap-device-helper
59329 60546 1.216888ms /usr/lib/snapd/snap-device-helper
61367 62512 1.145839ms /usr/lib/snapd/snap-device-helper
63210 64295 1.085042ms /usr/lib/snapd/snap-device-helper
64931 66128 1.197099ms /usr/lib/snapd/snap-device-helper
66359 67631 1.271963ms /usr/lib/snapd/snap-device-helper
68062 69177 1.115798ms /usr/lib/snapd/snap-device-helper
69381 70531 1.149892ms /usr/lib/snapd/snap-device-helper
70747 71896 1.148223ms /usr/lib/snapd/snap-device-helper
72125 73143 1.017093ms /usr/lib/snapd/snap-device-helper
73504 74830 1.32513ms /usr/lib/snapd/snap-device-helper
75095 76180 1.085042ms /usr/lib/snapd/snap-device-helper
76442 77741 1.299858ms /usr/lib/snapd/snap-device-helper
78026 79074 1.048803ms /usr/lib/snapd/snap-device-helper
79299 80471 1.171112ms /usr/lib/snapd/snap-device-helper
80801 81800 998.973µs /usr/lib/snapd/snap-device-helper
81994 83210 1.216888ms /usr/lib/snapd/snap-device-helper
83423 84774 1.350164ms /usr/lib/snapd/snap-device-helper
84990 86022 1.032829ms /usr/lib/snapd/snap-device-helper
86799 88173 1.374006ms /usr/lib/snapd/snap-device-helper
88953 90007 1.053094ms /usr/lib/snapd/snap-device-helper
152071 160794 8.723974ms snap-update-ns
167659 173197 5.537986ms snap-update-ns
175022 180223 5.201101ms /usr/lib/snapd/snap-exec
180223 294759 114.535093ms /snap/mumble/1141/bin/desktop-launch
185338 187860 2.521991ms /bin/date
202138 204674 2.536058ms /usr/bin/md5sum
205821 208400 2.57802ms /bin/cat
209475 213327 3.85189ms /bin/grep
229774 233689 3.914117ms /usr/bin/head
235225 238932 3.706932ms /usr/bin/head
240350 243963 3.612995ms /usr/bin/head
245653 249603 3.950119ms /usr/bin/head
251199 255003 3.803968ms /usr/bin/head
256641 260289 3.648042ms /usr/bin/head
261900 265924 4.024028ms /usr/bin/head
267593 271159 3.566026ms /usr/bin/head
272537 276211 3.673076ms /usr/bin/head
279445 283843 4.398107ms /bin/ln
285743 289454 3.710985ms /bin/rm
289957 293707 3.750801ms /bin/ln
294759 10415644 10.120885848s /snap/mumble/1141/bin/mumble
367547 377722 10.175943ms /bin/sh
370594 377614 7.02095ms /snap/mumble/1141/usr/bin/jackd
Total time: 10.415644884s
Total startup time: 10.422044663s
As for spotify, this seems to be slow for other reasons:
Yes this is just a local test I did to see if part of the issue is related to the size of the snap and its compression, because during first cold-cache startup, the kernel needs to decompress the snap squashfs filesystem, and that takes a significant amount of time for some snaps such as chromium, and also it appears spotify.
Mumble seems to be in the same situation, where the xz compressed .snap file is only 141 MB, but it’s 578M uncompressed. So it looks like most of the files that need to be decompressed for the real application to run are big dynamic libraries living in $SNAP/usr/lib/… which is what leads to the slowdown. Other large snaps like i.e. supertuxkart don’t have the same problem because while they are large snaps, most of their files are very small and the app doesn’t need to read them before displaying a window and loading the other files happens in the background whereas snaps like chromium, spotify, mumble, etc. need to decompress large dynamic library files before they can display their window.
Okay, so while compression might play a part in this piece, jack seems to be the bigger problem.
I do have jackd installed, but the mumble-snap can’t access it, therefore failing and retrying multiple times.
I tried installing the non-snap version, which starts almost instantly. However, as soon as I uninstall jackd, it takes longer as well. E.g. the snap startup-time minus compression and such. So, I am assuming this is a mumble problem afterall and there should be some way for mumble to notice that jack isn’t even installed and give up right away. I’ll create an issue on the mumble repository I guess.
While fixing Mumble’s detection of Jackd would help, it might also be helped from Snapd’s side by introducing an appropriate jack interface for Snaps to use. cc/ @jdstrand.
It appears the looping is solved in mumble 1.3.1. Sadly that version isn’t snapped yet. It’d be interesting to measure that version as well tho, I assume.
Here’s the numbers for spotify w/o any compression on my machine:
$ etrace -n=5 exec --no-trace --reinstall-snap --cmd-stderr=/dev/null --cmd-stdout=/dev/null --delete-snap-user-data --use-snap-run spotify
Total startup time: 4.098153703s
Total startup time: 4.180128398s
Total startup time: 4.845975432s
Total startup time: 4.890130566s
Total startup time: 4.36818876s
here’s reproducer instructions if you want to try it out yourself with a different snap or other compression options to mksquashfs:
$ snap install etrace --candidate
etrace (candidate) 0.8-3-g3a0801e from Ian Johnson (anonymouse67) installed
$ snap download spotify
Fetching snap "spotify"
Fetching assertions for "spotify"
Install the snap with:
snap ack spotify_41.assert
snap install spotify_41.snap
$ snap ack spotify_41.assert
$ snap install spotify_41.snap
spotify 1.1.26.501.gbe11e53b-15 from Spotify✓ installed
$ etrace -n=5 exec --no-trace --reinstall-snap --cmd-stderr=/dev/null --cmd-stdout=/dev/null --delete-snap-user-data --use-snap-run spotify
Total startup time: 8.009559806s
Total startup time: 7.78893528s
Total startup time: 7.800626833s
Total startup time: 7.21393162s
Total startup time: 7.7114391s
$ unsquashfs -d spotify spotify_41.snap
Parallel unsquashfs: Using 32 processors
21693 inodes (25649 blocks) to write
[==============================================================================================================================================================================================\] 25649/25649 100%
created 11978 files
created 2319 directories
created 9715 symlinks
created 0 devices
created 0 fifos
$ mksquashfs spotify spotify-uncomp.snap -noappend -no-fragments -all-root -no-xattrs -noI -noD -noF
Parallel mksquashfs: Using 32 processors
Creating 4.0 filesystem on spotify-uncomp.snap, block size 131072.
[==============================================================================================================================================================================================-] 15934/15934 100%
Exportable Squashfs 4.0 filesystem, gzip compressed, data block size 131072
uncompressed data, uncompressed metadata, no fragments,
no xattrs, uncompressed ids
duplicates are removed
Filesystem size 576651.40 Kbytes (563.14 Mbytes)
99.28% of uncompressed filesystem size (580847.60 Kbytes)
Inode table size 964326 bytes (941.72 Kbytes)
100.00% of uncompressed inode table size (964326 bytes)
Directory table size 631620 bytes (616.82 Kbytes)
100.00% of uncompressed directory table size (631620 bytes)
Number of duplicate files found 1210
Number of inodes 24012
Number of files 11978
Number of symbolic links 9715
Number of device nodes 0
Number of fifo nodes 0
Number of socket nodes 0
Number of directories 2319
Number of ids (unique uids + gids) 1
Number of uids 1
root (0)
Number of gids 1
root (0)
$ snap install spotify-uncomp.snap --dangerous
spotify 1.1.26.501.gbe11e53b-15 installed
$ etrace -n=5 exec --no-trace --reinstall-snap --cmd-stderr=/dev/null --cmd-stdout=/dev/null --delete-snap-user-data --use-snap-run spotify
Total startup time: 4.098153703s
Total startup time: 4.180128398s
Total startup time: 4.845975432s
Total startup time: 4.890130566s
Total startup time: 4.36818876s
* note that the --delete-snap-user-data option to etrace will back up the data before deleting by using snap save; you can restore it afterwards with snap restore (getting the snapshot ID from snap saved) if you don’t want to log back into spotify, etc. after doing this
Thanks Ian. So is it correct to say that there is a definite 3.0-3.2 second cost that is explicitly attributable to compression in that scenario? Looks like 4.0-4.8s uncompressed vs 7.2-8.0s compressed.
I wonder how that uncompressed speed compares to an ‘unpacked’ speed where there is genuinely no squashfs, and also to alternative compression algorithms.