Slow startup time for snaps?

snapd
1

Hello All –

When executing snaps like chromium, htop or telegram (mostly anything I try), I noticed them taking longer to start up then I was used to. There are two major subdivisions when considering startup time.

  1. First startup (before the fs cache is hot)
  2. Subsequent startup (after the fs cache is hot)

I find that both seem noticeably slower than apps that have counterparts in the .deb world. I looked to narrow this down a bit and provide a concrete example for people to look at, so I am looking on a bionic machine, with an SSD. and found a package that does a lot of startup tasks in its help generation (openstack-cli / python3-openstackclient).

bionic python3-openstackclient: version 3.14
snap openstack-cli: version 3.11 (also python3)

Obviously this is not strictly apples to apples, but I wanted to show something people could repeat and play around with. I see similar differences in startup time across a wide variety of snaps, and all of them have similar complications when doing direct comparisons.

To setup, I did:

sudo apt install python3-openstackclient python3-oslo-log
sudo snap install openstack-cli

My testing was basically run it a bunch of times. Rather than show you each iteration, here is the results of a representative run after a few attempts of each (warm cache case) to focus my question:

dpb@aries:~[]$ time /usr/bin/openstack --help > /dev/null

real	0m1.183s
user	0m1.136s
sys	    0m0.044s
dpb@aries:~[]$ time /snap/bin/openstack-cli --help > /dev/null

real	0m3.185s
user	0m3.092s
sys	    0m0.092s

As you can see, there is about a 2-3x difference in what should be something roughly equivalent. Again, I see this difference on many apps, but it’s difficult to quantify how long chromium takes to launch, for instance. Sometimes the difference is more like 50% more, sometimes higher.

Is anyone else experiencing this? Is it an issue with my configuration? Apparmor, etc?

dpb@aries:~[]$ snap version
snap 2.31
snapd 2.31
series 16
ubuntu 18.04
kernel 4.13.0-17-generic

Thanks.

2 Likes
2

typically snaps copy stuff around during their first start (bits that need to be writable etc), if you measure such things make sure to also measure the second startup time of the snap.

3

The time reported is after several executions, not the first time.

3 Likes
4

@dpb Thank you very much for the report.

@ogra The report we got from @dpb was careful enough to include a real world example with timings. We ought to do our part and verify that data, and explain exactly where the difference comes from.

@dpb We’ll look into your case, but meanwhile for comparison, here is a (strict) snap running in my machine:

$ which jmes
/snap/bin/jmes

$ time jmes
error: missing expression argument
jmes  0,02s user 0,03s system 74% cpu 0,070 total
1 Like
5

See Snaps seem slow to launch

@jamesh I wouldn’t normally ask for ‘progress’ on stuff but since this has been asked again…any more progress you haven’t reported here on this issue? :slight_smile:

6

@Ads20000 The problem and details described there seem unrelated to the situation described here. I suggest we keep those two conversations separate so we can focus on each of them.

7

I’ve not reviewed the openstack-cli snap, but I know that openstack is written in python with the python files in the read only /snap. If I were going to diagnose this, I would look to see what is happening with the .pyc files since python will try to write them out to to the readonly squashfs and move on, meaning no performance improvements from byte compilation.

I looked into this at one point for python3 and unfortunately, python3 (AFAICT) doesn’t allow you to relocate the __pycache__ directory (someone would have to look into python2, which IIRC openstack still uses). So, for the ufw snap, I hacked around this by creating a dangling symlink in the squashfs from usr/lib/python3/dist-packages/ufw/__pycache__ to /var/snap/ufw/current/usr/lib/python3/dist-packages/ufw/__pycache__, then in a wrapper script for the ufw command I did:

PYCACHE=$SNAP_DATA/usr/lib/python3/dist-packages/ufw/__pycache__
if [ ! -d "$PYCACHE" ] ; then
    mkdir -p "$PYCACHE" 2>/dev/null || true
fi

With the above, it undangles the symlink on first run and the .pyc files are written out to SNAP_DATA such that the second invocation doesn’t have to recompile them.

I did this a long time ago; it would be nice if we didn’t have to jump through such hoops though. Does snapcraft help us with this any now?

2 Likes
8

I like the inventiveness of this approach. bravo :slight_smile:

9

I dont see a reason why snapcraft couldnt create the .pyc files at snap build time … it isnt like they need to dynamically change or anything …

1 Like
10

You’re right @jdstrand, about half of the delta comes from the lack of .pyc files.

Time for the deb:

$ time /usr/bin/openstack --help > /dev/null     
/usr/bin/openstack --help > /dev/null  0,78s user 0,05s system 97% cpu 0,847 total

Time for the original snap:

$ time /snap/bin/openstack-cli --help > /dev/null                       
/snap/bin/openstack-cli --help > /dev/null  4,02s user 0,10s system 99% cpu 4,166 total

Time with snap hacked to include .pyc files.

$ sudo snap install ./openstack-cli_3.11.0_amd64.snap --dangerous
openstack-cli 3.11.0 installed
Snap openstack-cli is no longer tracking stable.

$ time /snap/bin/openstack-cli --help > /dev/null
/snap/bin/openstack-cli --help > /dev/null  2,61s user 0,14s system 98% cpu 2,781 total

For that to work I had to build the pyc files with the Python shipped in the snap itself.

About half of the delta is still there. Needs further investigation.

Update

I can also confirm that the remaining time difference is also unrelated to snaps, by copying the contents outside of the snap, to exclude any possibility of being related to the snap filesystem itself, and then executing the command inside it.

Doing that, the timing matches the time of executing the snap almost exactly:

$ pwd
/snap/openstack-cli

$ sudo cp -aL current current.copy
$ cd current.copy

$ time PYTHONPATH=$PWD/lib/python3.5/site-packages:$PWD/usr/lib/python3.5 $PWD/usr/bin/python3 $PWD/bin/openstack --help > /dev/null
PYTHONPATH=$PWD/lib/python3.5/site-packages:$PWD/usr/lib/python3.5   --help >  2,81s user 0,07s system 99% cpu 2,887 total

… and the snap:

$ time /snap/bin/openstack-cli --help > /dev/null
/snap/bin/openstack-cli --help > /dev/null  2,65s user 0,14s system 99% cpu 2,809 total

Conclusion

So, the current openstack-cli is indeed slower than the deb, but for reasons unrelated to any of the snap running infrastructure. One issue is the lack .pyc files, and there’s another issue that needs further investigation, but that can be reproduced by simply using the content of the snap completely outside anything snap-related.

On our end, the only thing we need to investigate for now is why the .pyc files were not generated by default by snapcraft. @sergiusens @kalikiana Can I leave that with one of you?

Otherwise, I think the issue is back with you, @dpb. Please let us know if you need further help.

3 Likes
11

@dpb @sergiusens @kalikiana Please see the update above.

12

FWIW there’s a rather obscure PYTHONDONTWRITEBYTECODE env variable that will stop Python from writing any *.pyc files.

1 Like
13

Thanks for the report, I think I know what this is. It is related to __pycache__/.pyc or lack thereof for them. I discussed options with one of the PyPA/PyPI maintainers and have a plan (not the ideal one, but a plan nonetheless).

2 Likes
14

Hi Gustavo,

Thanks for narrowing it down a bit. I’ll check a few more things and report any results I find, probably in a new thread.

I’m a bit unsure of what could be causing that, but clearly there is a difference in what the two commands are executing, so it’s where I will start. Could be a number of things… one is 2.11, the other is 2.14 for instance, Could be different modules enabled/shipped with each, etc.

Your .pyc conclusion is indeed a good portion of the problem and I look forward to seeing that addressed in some way in snapcraft.

Thanks all!

1 Like
15

@dpb Snapcraft should definitely be fixed to do the right thing by default, but you might not have to wait. In m tests I’ve just run “python3 -m compileall .” inside the root of the snap to compile every .pyc file automatically and in the right locations. Just note that the python version must be the one shipped in the snap itself if you’re using it to run things as commands later, otherwise the .pyc will be ignored.

3 Likes
16

Hi guys,

I came here, cause I was “feeling” this slowness for almost all of the snaps, when compared to their deb counterparts, so decided to google it around. I am talking subjectively here, but the first startup time is significantly higher than the deb ones!

Multiple packages that I have tested include Slack, Skype and even the Gnome Calculator on Ubuntu 18.04 beta 2 on my Dell XPS 9560 with a Core i7 7700HQ, 32 GB of RAM and nvme ssd

2 Likes
17

Hi there @ahmadsocrat

if you don’t mind some analysis, perhaps a new forum post would be in order focusing on just one of those snaps. Like, install both snap and deb, and then start up multiple times and put some timing information up.

Thanks!

18

I don’t have any exact data, but I can also confirm snap apps start up a lot slower than when I had installed them through deb packages.

Some examples: spotify, slack, atom.

It seems mostly to be affected the first time after a new boot. Are programs cached somehow after first run, and removed after boot?

I am using Ubuntu 18.04, fresh Install.

19

Please don’t be discouraged by my question - I hold the ubuntu developers in high regard, but are there
any news on this? It’s painful to wait for the start up of an app like its 1990. For me this is the reason I’ve switched back to .deb versions of the apps…

20

Snap applications are very slow to open, even on an SSD disk, sometimes it seems that the application has not been started.

Kubuntu 18.10 full upgrade proposed enable.

emanu@emanuc:~$ time libreoffice
main.go:192: cannot change mount namespace of snap “libreoffice” according to change mount (/snap/gtk-common-themes/701/share/icons/Suru /snap/libreoffice/83/data-dir/icons/Suru none bind,ro 0 0): cannot use “/snap/gtk-common-themes/701/share/icons/Suru” as bind-mount source: not a directory
ln: failed to create symbolic link ‘/home/emanu/snap/libreoffice/83/…/…/media/emanu/dati/Documenti’: No such file or directory
ln: failed to create symbolic link ‘/home/emanu/snap/libreoffice/83/…/…/media/emanu/dati/Scaricati’: No such file or directory
ln: failed to create symbolic link ‘/home/emanu/snap/libreoffice/83/…/…/media/emanu/dati/Musica’: No such file or directory
ln: failed to create symbolic link ‘/home/emanu/snap/libreoffice/83/…/…/media/emanu/dati/Immagini’: No such file or directory
ln: failed to create symbolic link ‘/home/emanu/snap/libreoffice/83/…/…/media/emanu/dati/Video’: No such file or directory
ln: failed to create symbolic link ‘/home/emanu/snap/libreoffice/83/…/…/media/emanu/dati/Documenti’: No such file or directory
ln: failed to create symbolic link ‘/home/emanu/snap/libreoffice/83/…/…/media/emanu/dati/Scaricati’: No such file or directory
ln: failed to create symbolic link ‘/home/emanu/snap/libreoffice/83/…/…/media/emanu/dati/Musica’: No such file or directory
ln: failed to create symbolic link ‘/home/emanu/snap/libreoffice/83/…/…/media/emanu/dati/Immagini’: No such file or directory
ln: failed to create symbolic link ‘/home/emanu/snap/libreoffice/83/…/…/media/emanu/dati/Video’: No such file or directory

real 0m43,593s
user 0m27,993s
sys 0m9,985s

snap info libreoffice
name: libreoffice
summary: LibreOffice is a powerful office suite including word processing and creation of spreadsheets,
slideshows and databases
publisher: Canonical✓
contact: http://www.libreoffice.org/get-help/community-support/
license: unset
description: |
LibreOffice is a powerful office suite – its clean interface and feature-rich tools help you
unleash your creativity and enhance your productivity. LibreOffice includes several applications
that make it the most powerful Free and Open Source office suite on the market: Writer (word
processing), Calc (spreadsheets), Impress (presentations), Draw (vector graphics and flowcharts),
Base (databases), and Math (formula editing).
commands:

  • libreoffice.base
  • libreoffice.calc
  • libreoffice.draw
  • libreoffice.filebug
  • libreoffice.impress
  • libreoffice
  • libreoffice.math
  • libreoffice.writer
    snap-id: CpUkI0qPIIBVRsjy49adNq4D6Ra72y4v
    tracking: stable
    refresh-date: yesterday at 18:59 CEST
    channels:
    stable: 6.1.1.2 (83) 501MB -
    candidate: 6.1.1.2 (83) 501MB -
    beta: ↑
    edge: ↑
    installed: 6.1.1.2 (83) 501MB -

snap version
snap 2.35.2+18.10
snapd 2.35.2+18.10
series 16
ubuntu 18.10
kernel 4.18.0-8-generic