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.