Slow cold start of snap firefox on Ubuntu 21.10

nicocarbone · October 15, 2021, 1:06pm

As discussed in the Feature Freeze Exception: Seeding the official Firefox snap in Ubuntu Desktop topic in discourse, I am using a fairly powerful PC (Rizen 2600, 32gb RAM, NVME SSD) and a cold start of firefox can take more than 10 seconds after updating to Ubuntu 21.10.

I don’t have anything against snap in general, in fact I prefer snapped apps when available. But right now this is not a good user experience. And people see it. See, for example, this review done by The Linux Experiment youtube channel: https://www.youtube.com/watch?v=SXfpbsCXUmE

I run a --trace-exec of firefox and this is the result:

snap run --trace-exec firefox
[sudo] contraseña para nicolas: 
/bin/bash: warning: setlocale: LC_ALL: cannot change locale (en_US.UTF-8)
amdgpu: os_same_file_description couldn't determine if two DRM fds reference the same file description.
If they do, bad things may happen!
Slowest 10 exec calls during snap run:
  0.475s snap-update-ns
  0.509s /usr/lib/snapd/snap-confine
  0.070s /snap/firefox/631/snap/command-chain/snapcraft-runner
  0.344s /snap/firefox/631/snap/command-chain/desktop-launch
  0.070s /usr/bin/dbus-send
  0.093s /usr/bin/xdg-settings
  0.061s /usr/bin/xdg-settings
  14.192s /snap/firefox/631/usr/lib/firefox/firefox
  10.890s /snap/firefox/631/usr/lib/firefox/firefox
  10.077s /snap/firefox/631/usr/lib/firefox/firefox
Total time: 28.494s

Subsequent runs of firefox start quickly, until next restart. If there is anything I can test or do, I am glad to help.

ogra · October 15, 2021, 1:10pm

i wonder if the amdgpu error is somewhat related to this … are you using the amdgpu driver from the archive or a third party one from AMD (which AFAIK installs into /opt … which in turn snapd can not see/access) ?

ppd · October 15, 2021, 1:33pm

For comparison, on Xeon E3.1230 v5, 16 GB RAM, SATA 3.3 SSD, Nvidia GPU (vendor driver):

maxi@maxi-desktop:~$ snap run --trace-exec firefox
[sudo] password for maxi: 
Gtk-Message: 15:23:36.317: Failed to load module "canberra-gtk-module"
Gtk-Message: 15:23:36.336: Failed to load module "canberra-gtk-module"
[GFX1-]: glxtest: libEGL missing
[GFX1-]: glxtest: libEGL missing

###!!! [Parent][MessageChannel] Error: (msgtype=0x390078,name=PContent::Msg_DestroyBrowsingContextGroup) Closed channel: cannot send/recv


###!!! [Parent][MessageChannel] Error: (msgtype=0x390078,name=PContent::Msg_DestroyBrowsingContextGroup) Closed channel: cannot send/recv


###!!! [Child][MessageChannel] Error: (msgtype=0x6A0024,name=PNecko::Msg_RequestContextAfterDOMContentLoaded) Channel closing: too late to send/recv, messages will be lost


###!!! [Child][MessageChannel] Error: (msgtype=0x6A0024,name=PNecko::Msg_RequestContextAfterDOMContentLoaded) Channel closing: too late to send/recv, messages will be lost


###!!! [Parent][MessageChannel] Error: (msgtype=0x390078,name=PContent::Msg_DestroyBrowsingContextGroup) Closed channel: cannot send/recv


###!!! [Parent][MessageChannel] Error: (msgtype=0x390078,name=PContent::Msg_DestroyBrowsingContextGroup) Closed channel: cannot send/recv


###!!! [Parent][MessageChannel] Error: (msgtype=0x390078,name=PContent::Msg_DestroyBrowsingContextGroup) Closed channel: cannot send/recv


###!!! [Parent][MessageChannel] Error: (msgtype=0x390078,name=PContent::Msg_DestroyBrowsingContextGroup) Closed channel: cannot send/recv


###!!! [Parent][MessageChannel] Error: (msgtype=0x390078,name=PContent::Msg_DestroyBrowsingContextGroup) Closed channel: cannot send/recv


###!!! [Parent][MessageChannel] Error: (msgtype=0x390078,name=PContent::Msg_DestroyBrowsingContextGroup) Closed channel: cannot send/recv


###!!! [Parent][MessageChannel] Error: (msgtype=0x390078,name=PContent::Msg_DestroyBrowsingContextGroup) Closed channel: cannot send/recv


###!!! [Parent][MessageChannel] Error: (msgtype=0x390078,name=PContent::Msg_DestroyBrowsingContextGroup) Closed channel: cannot send/recv


###!!! [Child][MessageChannel] Error: (msgtype=0x6A0024,name=PNecko::Msg_RequestContextAfterDOMContentLoaded) Channel closing: too late to send/recv, messages will be lost


###!!! [Parent][MessageChannel] Error: (msgtype=0x390078,name=PContent::Msg_DestroyBrowsingContextGroup) Closed channel: cannot send/recv


###!!! [Parent][MessageChannel] Error: (msgtype=0x390078,name=PContent::Msg_DestroyBrowsingContextGroup) Closed channel: cannot send/recv


###!!! [Parent][MessageChannel] Error: (msgtype=0x390078,name=PContent::Msg_DestroyBrowsingContextGroup) Closed channel: cannot send/recv


###!!! [Parent][MessageChannel] Error: (msgtype=0x390078,name=PContent::Msg_DestroyBrowsingContextGroup) Closed channel: cannot send/recv


###!!! [Child][MessageChannel] Error: (msgtype=0x6A0024,name=PNecko::Msg_RequestContextAfterDOMContentLoaded) Channel closing: too late to send/recv, messages will be lost


###!!! [Child][MessageChannel] Error: (msgtype=0x390141,name=PContent::Msg_ScriptError) Channel closing: too late to send/recv, messages will be lost


###!!! [Child][MessageChannel] Error: (msgtype=0x390141,name=PContent::Msg_ScriptError) Channel closing: too late to send/recv, messages will be lost


###!!! [Child][MessageChannel] Error: (msgtype=0x23002F,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost


###!!! [Child][MessageChannel] Error: (msgtype=0x23002F,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost


###!!! [Child][MessageChannel] Error: (msgtype=0x23002F,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost


###!!! [Child][MessageChannel] Error: (msgtype=0x23002F,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost


###!!! [Child][MessageChannel] Error: (msgtype=0x23002F,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost


###!!! [Child][MessageChannel] Error: (msgtype=0x23002F,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost


###!!! [Child][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost

Slowest 10 exec calls during snap run:
  0.834s snap-update-ns
  0.990s /usr/lib/snapd/snap-confine
  0.209s /snap/firefox/631/snap/command-chain/desktop-launch
  0.100s /usr/bin/dbus-send
  0.114s /usr/bin/xdg-settings
  0.062s /usr/bin/xdg-settings
  0.066s /usr/bin/xdg-settings
  2.493s /snap/firefox/631/usr/lib/firefox/firefox
  0.910s /snap/firefox/631/usr/lib/firefox/firefox
  1.808s /snap/firefox/631/usr/lib/firefox/firefox
Total time: 8.182s

ogra · October 15, 2021, 1:38pm

yep, definitely faster … similar here on an intel GPU …

nicocarbone · October 15, 2021, 1:44pm

I am running the default mesa config from Ubuntu 21.10 on a Radeon 5500XT.

Edit: output of glxinfo

OpenGL renderer string: Radeon RX 5500 XT (NAVI14, DRM 3.41.0, 5.13.0-051300-generic, LLVM 12.0.1)

ogra · October 15, 2021, 2:04pm

I have moved the post to the snapd category, they probably have more ideas and more fine grained debugging suggestions …

paultruzzi · October 17, 2021, 11:01pm

I have the same issue:

Gtk-Message: 15:57:41.476: Failed to load module “canberra-gtk-module” [GFX1-]: glxtest: libEGL missing

This was an upgrade from 21.04 to 21.10. The old installation had Firefox installed from … well probably a .deb. I’ve removed and reinstalled the new Firefox snap. I get the same error when I launch it from the terminal.

When I launch from the graphical interface; toolbar> Applications> Internet> Firefox I get a different error;

Firefox is already running, but is not responding. To use Firefox, you must first close the existing Firefox process, restart your device, or use a different profile.

This happens even following a full shutdown and restart.

ogra · October 18, 2021, 6:28am

i don’t think the glxtest output is necessarily an error, do you see a massive slow down when starting Firefox (i.e. more than 10 sec in the case where it does not complain about an already running instance) ?

the second one surely deserves a bug report at the mozilla bugtracker (it might have to do with your old profile, but i’m just guessing here)

ijohnson · October 18, 2021, 3:42pm

I would really like to see output from using etrace on this system, but I need to finish supporting Wayland on etrace which I haven’t gotten around to yet unfortunately

nicocarbone · October 19, 2021, 2:00pm

I don’t know if it helps much, but here is the etrace I get login into the X11 session:

❯ snap run --trace-exec firefox
[sudo] contraseña para nicolas: 
/bin/bash: warning: setlocale: LC_ALL: cannot change locale (en_US.UTF-8)
Gtk-Message: 10:57:47.071: Failed to load module "canberra-gtk-module"
Gtk-Message: 10:57:47.166: Failed to load module "canberra-gtk-module"
amdgpu: os_same_file_description couldn't determine if two DRM fds reference the same file description.
If they do, bad things may happen!
amdgpu: os_same_file_description couldn't determine if two DRM fds reference the same file description.
If they do, bad things may happen!

###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost

Slowest 10 exec calls during snap run:
  0.617s snap-update-ns
  0.661s /usr/lib/snapd/snap-confine
  0.309s /snap/firefox/631/snap/command-chain/desktop-launch
  0.090s /usr/bin/dbus-send
  0.108s /usr/bin/xdg-settings
  19.702s /snap/firefox/631/usr/lib/firefox/firefox
  21.636s /snap/firefox/631/usr/lib/firefox/firefox
  23.317s /snap/firefox/631/usr/lib/firefox/firefox
  35.473s /snap/firefox/631/usr/lib/firefox/firefox
  1.928s /snap/firefox/631/usr/lib/firefox/firefox
Total time: 37.636s

ppd · October 19, 2021, 2:03pm

I think @ijohnson is referring to this: https://snapcraft.io/blog/introducing-etrace-a-multi-purpose-application-profiling-tool

nicocarbone · October 19, 2021, 2:35pm

Ahh, ok. Right. I will try to run that etrace then and see what I get.

nicocarbone · October 23, 2021, 2:14am

Sorry for the delay. Here is the etrace of snap firefox under X11:

❯ etrace exec firefox --no-window-wait
[sudo] contraseña para nicolas: 
/bin/bash: warning: setlocale: LC_ALL: cannot change locale (en_US.UTF-8)
Gtk-Message: 23:12:57.014: Failed to load module "canberra-gtk-module"
Gtk-Message: 23:12:57.164: Failed to load module "canberra-gtk-module"
amdgpu: os_same_file_description couldn't determine if two DRM fds reference the same file description.
If they do, bad things may happen!

###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost

45 exec calls during snap run:
     Start     Stop      Elapsed        Exec
     0         1160408   1.16040802s    /snap/bin/firefox
     89149     99820     10.6709ms      /usr/lib/snapd/snap-seccomp
     139976    1138618   998.641967ms   snap-update-ns
     1145961   1155927   9.965896ms     snap-update-ns
     1160408   1246465   86.057901ms    /usr/lib/snapd/snap-exec
     1246465   1609097   362.632036ms   /snap/firefox/631/snap/command-chain/desktop-launch
     1300460   1308629   8.16822ms      /usr/bin/date
     1328831   1335477   6.645917ms     /usr/bin/chmod
     1338127   1342730   4.603147ms     /usr/bin/md5sum
     1344412   1348675   4.262208ms     /usr/bin/cat
     1350801   1354166   3.365039ms     /usr/bin/md5sum
     1357116   1359768   2.651929ms     /usr/bin/cat
     1360646   1398432   37.786006ms    /usr/bin/grep
     1399451   1421991   22.539854ms    /usr/bin/snapctl
     1428792   1461045   32.253026ms    /usr/bin/mkdir
     1463987   1494467   30.480146ms    /usr/bin/realpath
     1496048   1503150   7.102012ms     /usr/bin/realpath
     1507277   1515342   8.065938ms     /snap/firefox/631/gnome-platform/usr/bin/xdg-user-dirs-update
     1517654   1522541   4.887104ms     /usr/bin/realpath
     1525424   1532457   7.033824ms     /usr/bin/realpath
     1534472   1539393   4.920959ms     /usr/bin/realpath
     1541477   1544811   3.334045ms     /usr/bin/realpath
     1546633   1552613   5.980968ms     /usr/bin/realpath
     1555014   1561764   6.750106ms     /usr/bin/realpath
     1563305   1566795   3.489971ms     /usr/bin/realpath
     1568923   1575534   6.61087ms      /usr/bin/realpath
     1578877   1585140   6.263017ms     /usr/bin/mkdir
     1585966   1593083   7.117033ms     /usr/bin/ln
     1595592   1602618   7.02691ms      /usr/bin/rm
     1602921   1607728   4.806995ms     /usr/bin/ln
     1609097   1623026   13.92889ms     /snap/firefox/631/tmpdir
     1618188   1622757   4.569053ms     /snap/firefox/631/gnome-platform/usr/bin/xdg-user-dir
     1623026   1648378   25.352001ms    /snap/firefox/631/firefox.launcher
     1628077   1648000   19.922971ms    /usr/bin/cut
     1628854   1641893   13.038873ms    /usr/bin/id
     1641937   1647760   5.82385ms      /usr/bin/getent
     11187045  31544597  20.357552051s  /snap/firefox/631/usr/lib/firefox/firefox
     11635943  31144908  19.508965015s  /snap/firefox/631/usr/lib/firefox/firefox
     13681891  31222564  17.540673017s  /snap/firefox/631/usr/lib/firefox/firefox
     14725740  14858940  133.19993ms    /usr/bin/xdg-settings
     14753316  14858636  105.319976ms   /usr/bin/dbus-send
     15005095  31151355  16.146260023s  /snap/firefox/631/usr/lib/firefox/firefox
     15203976  15271495  67.518949ms    /usr/bin/xdg-settings
     15539816  15609341  69.525003ms    /usr/bin/dbus-send
     15753404  15833441  80.036163ms    /usr/bin/xdg-settings
Total time:  32.593804836s
Total startup time: 32.632490707

nicocarbone · October 26, 2021, 3:12pm

Is there anything else I can do to help solving (or, at least, diagnosing) this issue? Am I the only one with this problem?

ijohnson · October 26, 2021, 4:06pm

The output you have suggests that there is basically 1.6s before the handoff to the firefox binary itself happens, and then it is taking the firefox binary a significant amount of time to do anything so I would assume that this is not anything to do with snapd helpers but rather with something inside firefox having issues with snap confinement on your machine. Probably needs someone who knows the internals about firefox to take a look

edurojas · March 15, 2022, 3:26am

Hi! I did some fast testing using:

AMD CPU Thinkpad t14s with Ryzen AMD 4780PRO
Intel CPU Thinkpad T460 (much older) with Intel CPU

(sorry for images instead of text, but didn’t have much time)

Fresh (Cold) star Firefox 98.0.1 on AMD:

Subsequent Runs FireFox 98.0.1 on AMD:

I have to point out that there’s a delay or overhead with the amdgpu: os_same_file_description which seems to me to increase time.

Fresh (Cold) start Firefox 98.0.1 on Intel:

Subsequent Runs FireFox 98.0.1 on Intel:

Note: Resh (Cold) start means that is after reboot, not a fresh install or after update.

Maybe this help to investigate why Firefox Snap opens so slow in modern hardware

edurojas · April 24, 2022, 10:14pm

Hi! I did a fresh install of Ubuntu 22.04 on my Thinkpad t14s Gen 1 with AMD Reinor and FireFox feels more faster in both cold and hot start up I can’t do test with --trace-exec because for some reason now this command add a lot of overhead with a bunch of errors and make the snap start up much slower.

So i did a manual test Firefox 99.0.1-1 snap rev 1232:

Cold start 21.10 = aprox 15 sec
Hot start 21.10 = aprox 6 sec
Cold start 22.04 = aprox 6 sec
Hot start 22.04 = aprox 2 sec

But I can say that now feel faster than in 21.10 (still needs improvement), another thing that I have notice is that if you have any form of power manager like TLP or cpu-autofreq and this uses the “power save” gobernor instead of schedutils (default for AMD) the start up time of snaps gets a hit and slow down the startup. So for me only use schedutils governor the snaps are more snappy and faster to start up.

edurojas · July 12, 2022, 11:40pm

Just for completeness, after this improvements.

https://snapcraft.io/blog/improving-firefox-snap-performance-part-3

With FireFox 102.0.2-1 snap rev 231 in my Thinkpad t14s gen 1 the cold start went from 4-5s to 1.3s.

Impressive improvements!

simonsaysthis · July 13, 2022, 5:08pm

Same here. FF starts pleasantly fast for me now so that I cannot make out the difference to using the deb package