An investigation into snap startup speed

Test Cases

  • For this investigation I chose to benchmark the following 5 snaps: libreoffice, gnome-calculator, chromium, gnome-logs, and irccloud-desktop.

  • Tracing was performed using a modified version of the --trace-exec util in snapd for more detailed outputs.

  • Startup times were measured using Ken VanDine’s auto_close_win_id script to ensure that each snap was terminated as soon as it became visible.

  • Actual total startup & desktop-launch elapsed times were measured using:

    • ./auto_close_win_id <snap_name> & SNAP_DESKTOP_DEBUG=true /usr/bin/time snap run <snap_name>
  • Before each “First Run” measurement, the following was executed:

    • snap remove <snap_name> && rm -rf ~/.config/<snap_name> ~/snap/<snap_name> && snap install <snap_name>

libreoffice

First Run

snap run --trace-exec: https://pastebin.ubuntu.com/p/CcV8bJP7g4/
Actual desktop-launch elapsed time: 0.179079001
Actual total startup time: 4.11

Second Run

snap run --trace-exec: https://pastebin.ubuntu.com/p/bcnfKnnvKx/
Actual desktop-launch elapsed time: 0.049050456
Actual total startup time: 1.56

gnome-calculator

First Run

snap run --trace-exec: https://pastebin.ubuntu.com/p/RjcB9qjXRd/
Actual desktop-launch elapsed time: 0.152135141
Actual total startup time: 1.05

Second Run

snap run --trace-exec: https://pastebin.ubuntu.com/p/p6ttmGPgkH/
Actual desktop-launch elapsed time: 0.049452810
Actual total startup time: 0.54

chromium

First Run

snap run --trace-exec: https://pastebin.ubuntu.com/p/T7s9XHh9hM/
Actual desktop-launch elapsed time: 0.511440921*
Actual total startup time: 4.13

Second Run

snap run --trace-exec: https://pastebin.ubuntu.com/p/xD729GXGrh/
Actual desktop-launch elapsed time: 0.054895628
Actual total startup time: 0.56

gnome-logs

First Run

snap run --trace-exec: https://pastebin.ubuntu.com/p/BWnfXDv7Jz/
Actual desktop-launch elapsed time: 0.160419964
Actual total startup time: 1.07

Second Run

snap run --trace-exec: https://pastebin.ubuntu.com/p/7HkMKscSV4/
Actual desktop-launch elapsed time: 0.054980124
Actual total startup time: 0.56

irccloud-desktop

First Run

snap run --trace-exec: https://pastebin.ubuntu.com/p/ngctCnWjgF/
Actual desktop-launch elapsed time: 0.259691098*
Actual total startup time: 2.61

Second Run

snap run --trace-exec: https://pastebin.ubuntu.com/p/Q8RG7j8v5y/
Actual desktop-launch elapsed time: 0.054142831
Actual total startup time: 0.58

Findings

I think the best example to use in summing up what was observed here is libreoffice. Let’s take a look at the trace-exec for libreoffice’s first run.

The first thing to note is that libreoffice’s actual first run startup time is 4.110s, while the trace-exec log states 10.208s. This is because running strace against a process (and its children) is bound to slow it down a little - and not by some linear proportion either, mind you. For example: line 12 states that desktop-launch ran for 2.682s - that’s roughly 26% of the total 10.208s startup - however, in normal execution, desktop-launch runs for just 0.179s of its actual 4.110s startup - only 4% in reality.

Although the actual timings in our trace-exec are disproportional, their sequencing will at least be correct. Which brings us to the most interesting part of the findings. We know that just 4% of the snap’s startup is taken up by desktop-launch, the question then is: what is the snap doing for the other 96%? We can break down almost all of the 10s recorded in that log into 3 pieces:

  • 0.522s spent on snap-confine (line 9)
  • then 2.682s spent on desktop-launch (lines 40 to 110)
  • then 6,912s spent on libreoffice.wrapper (line 111 to 126)

It’s probably** safe to say that snap-confine will be using less startup time than desktop-launch, so worst case is another 4% there. That’s at least 92% of the startup time left purely in the hands of libreoffice.wrapper.

It’s hard not to assume at this stage that the slowness of snaps is really more of a snap-specific problem than a greater infrastructural one, but I have to believe it’s not that black and white either. Perhaps yes, most of a snap’s startup time is spent on snap-specific logic, and yes, massive gains can certainly be had with snap-specific tweaks, but it doesn’t necessarily eliminate the possibility that some improvement to snapd could speed things up here too.

*This snap uses an older, less optimised version of the desktop-launch script, thus has a noticeably slower startup time than the others.

**It would be great to have an equivalent of SNAP_DESKTOP_DEBUG=true for snap-confine that gave us an actual elapsed time outside of stracing.

7 Likes

What hardware did you use to test this?

Can you re-run these benchmarks, removing the gnome-3-* snap and the gtk-common-themes snaps before starting the application? I was doing this for my tests and noticed a more significant startup time than you are measuring here, so it would be good to see if your setup also exhibits this behavior. Thanks

1 Like

libreoffice, gnome-calculator, gnome-logs, and irccloud-desktop all require these snaps so it’s not possible to retest without them installed.

chromium requires only gtk-common-themes, but even with all gnome-3-* snaps removed, I still get the same results.

Memory: 5.0 GiB
Processor: Intel® Core™ i9-9880H CPU @ 2.30GHz × 8
Graphics: AMD® Radeon pro 560x
Virtualisation: KVM

1 Like

All of these snaps should have the gnome-* content snaps listed as default providers, so when you install them, if the content snap is not installed snapd should automatically install those AFAIK. If it doesn’t do that it’s probably a snapd bug.

What I have been doing to test these sorts of snaps is something along the lines of:

#!/bin/bash -e

# remove all the relevant snaps
snap remove libreoffice gnome-3-28-1804 gtk-common-themes

# install the snap under testing
snap install libreoffice

# clear out any caching
rm -rf ~/.config/libreoffice ~/snap/libreoffice
sudo sync
for i in 1 2 3; do 
    sudo sysctl -q vm.drop_caches="$i"
done
sudo /usr/lib/snapd/snap-discard-ns libreoffice

# run the test

Ah, I see what you mean now, you meant remove these snaps before installing the application. Yeah ok. Another major difference between your testing and mine is the extent to which you’re clearing caches.

So here’s libreoffice again when testing with your script:

libreoffice

First Run

snap run --trace-exec: https://pastebin.ubuntu.com/p/wgXmc9Y9KP/
Actual desktop-launch elapsed time: 0.536814884
Actual total startup time: 5.63

Second Run (No real difference)

snap run --trace-exec: https://pastebin.ubuntu.com/p/SV5f6dD86j/
Actual desktop-launch elapsed time: 0.051198753
Actual total startup time: 1.29

Findings

Let’s dig into what’s changed on the first run trace-exec:

Again we see that while libreoffice’s actual first run time was 5.63s, the trace-exec log states a much larger 11.514s, and again, the timings of subprocesses are not proportional to each other. For example: line 7 states that desktop-launch ran for 3.008s - roughly 26% of the total 11.514s startup - however, in normal execution, desktop-launch runs for just 0.537s of its actual 5.630s startup - a little under 10% in reality.

So knowing that 10% of the snap’s startup is taken up by desktop-launch, we look at what the snap is doing for the other 90%. The 11.5s recorded can be broken down into 3 main parts:

  • 0.581s spent on snap-confine (line 4)
  • then 3.008s spent on desktop-launch (lines 35 to 117)
  • then 7,804s spent on libreoffice.wrapper (line 118 to 132)

Seeing that the time spent on snap-confine only rose by a fraction, I’ll keep close to my 4% guesstimation there. That’s at least 85% of the startup time still purely in the hands of libreoffice.wrapper.

Granted, there is certainly more going on in desktop-launch as previously measured, but the story hasn’t really changed a lot.

1 Like

Apologies, let me clarify what I mean by this.

What I mean is that the idea of snap-specific improvements having highest impact still holds. The fact that desktop-launch is 3x slower in these measurements than before of course cannot be ignored. A half-second cold start definitely feels like something we can improve on.

Thanks for pointing this out @ijohnson.

1 Like

For completeness, here are the timings for the other snaps:

gnome-calculator

First Run

snap run --trace-exec: https://pastebin.ubuntu.com/p/B6PQz73cSr/
Actual desktop-launch elapsed time: 0.533724216
Actual total startup time: 2.07

chromium

First Run

snap run --trace-exec: https://pastebin.ubuntu.com/p/hTmCMgwW5D/
Actual desktop-launch elapsed time: 0.643954821
Actual total startup time: 4.64

gnome-logs

First Run

snap run --trace-exec: https://pastebin.ubuntu.com/p/6jNbhD3jbw/
Actual desktop-launch elapsed time: 0.510977055
Actual total startup time: 2.60

irccloud-desktop

First Run

snap run --trace-exec: https://pastebin.ubuntu.com/p/JMqqTy2Y2B/
Actual desktop-launch elapsed time: 0.482481699
Actual total startup time: 3.62

1 Like