[snap] On Groovy, Chromium snap takes much longer to load the first time after reboot

[Alexander Browne]

I upgraded from Focal to Groovy, and now the first launch of the Chromium snap after a reboot is taking much longer than before. On my main home laptop it takes over 30 seconds, while under Focal I don't remember it taking more than 10 seconds.

I tried another computer I could erase. On Groovy that computer takes nearly a minute to launch the Chromium snap after rebooting. Then I clean installed Focal on the same machine, and the Chromium snap takes just under 10 seconds to launch after a reboot. For both I installed all updates, and I let the computer sit idle for a few minutes after rebooting to try to rule out other activity.

I haven’t noticed the change for any other snap, although I don’t use any that I ever noticed as much of a launch delay as Chromium. (VS Code for one doesn’t seem slower — certainly not taking nearly a minute — but I haven't done a real comparison like for Chromium.)

ProblemType: Bug
DistroRelease: Ubuntu 20.10
ProcVersionSignature: Ubuntu 5.8.0-25.26-generic 5.8.14
Uname: Linux 5.8.0-25-generic x86_64
ApportVersion: 2.20.11-0ubuntu50
Architecture: amd64
CasperMD5CheckResult: skip
CurrentDesktop: ubuntu:GNOME
Date: Tue Oct 20 21:29:20 2020
InstallationDate: Installed on 2020-04-01 (202 days ago)
InstallationMedia: Ubuntu 20.04 LTS "Focal Fossa" - Beta amd64 (20200331)
Snap: chromium 87.0.4280.20 (latest/beta)
SnapSource: ubuntu/+source/chromium-browser
UpgradeStatus: Upgraded to groovy on 2020-10-17 (3 days ago)

[Olivier Tilloy (osomon)]

Thanks for the report Alexander. This is a concerning regression indeed.
I see in the data attached by apport that you're using the chromium snap from the beta channel.
Were you installing from the beta channel in both cases? Does switching to the stable channel make a difference?

Could you run chromium with the following command in both configurations, and attach the output printed in the terminal after closing the window?

    snap run --trace-exec chromium

Thanks!

[Olivier Tilloy (osomon)]

Testing in fully up-to-date focal and groovy virtual machines, I do see a slightly longer startup time in groovy after a cold boot, but it's not a 3× increase.

[Alexander Browne (elcste)]

On my main/home computer I've only tried beta channel, but with the other computer I've tried both stable and beta. It doesn't seem to make a difference.

Here is what I got for that command on Groovy:

STABLE

ab@mb:~$ snap run --trace-exec chromium
[sudo] password for ab:
Gtk-Message: 17:25:22.173: Failed to load module "canberra-gtk-module"
Gtk-Message: 17:25:22.194: Failed to load module "canberra-gtk-module"
[4206:4206:1022/172540.610350:ERROR:sandbox_linux.cc(374)] InitializeSandbox() called with multiple threads in process gpu-process.
Slowest 10 exec calls during snap run:
  0.254s snap-update-ns
  0.436s /usr/lib/snapd/snap-confine
  0.618s /snap/chromium/1362/bin/desktop-launch
  0.115s /snap/chromium/1362/bin/chromium.launcher
  0.118s /usr/bin/dbus-send
  0.227s /usr/bin/xdg-settings
  0.121s /snap/chromium/1362/usr/lib/chromium-browser/chrome
  0.094s /usr/bin/xdg-settings
  36.826s /proc/self/exe
  46.485s /snap/chromium/1362/usr/lib/chromium-browser/chrome
Total time: 47.862s

BETA

ab@mb:~$ snap run --trace-exec chromium
[sudo] password for ab:
Gtk-Message: 17:31:19.827: Failed to load module "canberra-gtk-module"
Gtk-Message: 17:31:19.851: Failed to load module "canberra-gtk-module"
[4553:4553:1022/173142.433976:ERROR:sandbox_linux.cc(374)] InitializeSandbox() called with multiple threads in process gpu-process.
Slowest 10 exec calls during snap run:
  0.228s snap-update-ns
  0.389s /usr/lib/snapd/snap-confine
  0.095s /snap/chromium/1357/snap/command-chain/snapcraft-runner
  0.607s /snap/chromium/1357/bin/desktop-launch
  0.072s /usr/bin/snapctl
  0.123s /snap/chromium/1357/bin/chromium.launcher
  0.115s /usr/bin/dbus-send
  0.315s /usr/bin/xdg-settings
  31.778s /proc/self/exe
  44.545s /snap/chromium/1357/usr/lib/chromium-browser/chrome
Total time: 45.843s

I deleted the chromium data (rm -r ~/snap/chromium), launched chromium once, then rebooted and waited briefly, and finally ran the command. Then I refreshed channels and did the same again.

If it's useful I can reinstall Focal on that computer when I'm back at work tomorrow, and get the same info.

[Alexander Browne (elcste)]

And for my main computer, Groovy/Chromium beta channel *with* my normal profile:

alexander@elcste:~$ snap run --trace-exec chromium
[sudo] password for alexander:
Gtk-Message: 21:19:28.762: Failed to load module "canberra-gtk-module"
Gtk-Message: 21:19:28.790: Failed to load module "canberra-gtk-module"
[3494:3494:1022/211947.584671:ERROR:sandbox_linux.cc(374)] InitializeSandbox() called with multiple threads in process gpu-process.
Slowest 10 exec calls during snap run:
  0.198s snap-update-ns
  0.330s /usr/lib/snapd/snap-confine
  0.058s /usr/bin/head
  0.495s /snap/chromium/1366/bin/desktop-launch
  0.045s /usr/bin/snapctl
  0.098s /snap/chromium/1366/bin/chromium.launcher
  0.134s /usr/bin/dbus-send
  0.196s /usr/bin/xdg-settings
  35.202s /proc/self/exe
  43.764s /snap/chromium/1366/usr/lib/chromium-browser/chrome
Total time: 44.773s

I could try stable channel and a fresh profile using another user account if it's helpful.

[Olivier Tilloy (osomon)]

Thanks for the data Alexander. To debug this further, could you install etrace, run the chromium snap through it after a cold boot, and share the output?

    sudo snap install etrace --candidate --classic
    etrace exec /snap/bin/chromium

[Alexander Browne (elcste)]

Here's after a reboot, again with a clean profile that's been opened one time, stable channel on up-to-date Groovy:

ab@mb:~$ etrace exec /snap/bin/chromium
2020/10/23 10:27:06 xdotool.go:84:
Gtk-Message: 10:27:14.094: Failed to load module "canberra-gtk-module"
Gtk-Message: 10:27:14.116: Failed to load module "canberra-gtk-module"
[11797:11797:1023/102734.021699:ERROR:sandbox_linux.cc(374)] InitializeSandbox() called with multiple threads in process gpu-process.
61 exec calls during snap run:
     Start Stop Elapsed Exec
     0 472100 472.100019ms /snap/bin/chromium
     27013 37971 10.958909ms /usr/lib/snapd/snap-seccomp
     103312 105487 2.174139ms /usr/lib/snapd/snap-device-helper
     105838 107959 2.121925ms /usr/lib/snapd/snap-device-helper
     108319 110501 2.181053ms /usr/lib/snapd/snap-device-helper
     110850 113080 2.230882ms /usr/lib/snapd/snap-device-helper
     113421 115489 2.067089ms /usr/lib/snapd/snap-device-helper
     115772 118021 2.249002ms /usr/lib/snapd/snap-device-helper
     118335 120568 2.233028ms /usr/lib/snapd/snap-device-helper
     120867 125847 4.980087ms /usr/lib/snapd/snap-device-helper
     126198 128540 2.342939ms /usr/lib/snapd/snap-device-helper
     128860 131577 2.716064ms /usr/lib/snapd/snap-device-helper
     131940 134634 2.694845ms /usr/lib/snapd/snap-device-helper
     134973 137454 2.481937ms /usr/lib/snapd/snap-device-helper
     137806 140505 2.698183ms /usr/lib/snapd/snap-device-helper
     140962 143770 2.808809ms /usr/lib/snapd/snap-device-helper
     144108 146301 2.193927ms /usr/lib/snapd/snap-device-helper
     146591 148778 2.187013ms /usr/lib/snapd/snap-device-helper
     149217 151494 2.276897ms /usr/lib/snapd/snap-device-helper
     151847 154367 2.520799ms /usr/lib/snapd/snap-device-helper
     155422 157877 2.454996ms /usr/lib/snapd/snap-device-helper
     165157 167555 2.398014ms /usr/lib/snapd/snap-device-helper
     168947 171360 2.413034ms /usr/lib/snapd/snap-device-helper
     172826 175012 2.186059ms /usr/lib/snapd/snap-device-helper
     176098 178416 2.318859ms /usr/lib/snapd/snap-device-helper
     179435 182003 2.568006ms /usr/lib/snapd/snap-device-helper
     183077 185662 2.584934ms /usr/lib/snapd/snap-device-helper
     209460 445437 235.977888ms snap-update-ns
     458566 468766 10.200023ms snap-update-ns
     472100 573029 100.929975ms /usr/lib/snapd/snap-exec
     573029 582269 9.239912ms /snap/chromium/1362/command-chromium.wrapper
     582269 1204112 621.842145ms /snap/chromium/1362/bin/desktop-launch
     667310 679414 12.10308ms /bin/date
     771656 780951 9.294986ms /usr/bin/md5sum
     784470 793044 8.574008ms /bin/cat
     795722 803555 7.83205ms /usr/bin/md5sum
     805881 811655 5.774974ms /bin/cat
     813513 832447 18.934011ms /bin/grep
     839522 868767 29.24...

[Olivier Tilloy (osomon)]

Thanks Alexander, that's useful data. What this shows is that it's the chromium executable that is taking a very long time to start up on cold boot, there doesn't seem to be any significant overhead from snapd and wrapper scripts.

Next thing to try is:

    snap run --strace="-vvr" chromium 2> chromium.trace

and attach the resulting chromium.trace file. This should give us more information about what is taking so long when running the chromium executable for the first time after a cold boot.

[Alexander Browne (elcste)]

FWIW I hadn't tried Google Chrome on this computer, so I installed it (same stable version as the snap), and it loads with normal speed on cold boot and subsequently.

[Olivier Tilloy (osomon)]

Marking confirmed because this was also reported as bug #1901432.

[Sergio Schvezov (sergiusens)]

If I started once already, deleting the fontconfig cache ("rm ~/snap/chromium/common/.cache/fontconfig") brings back some slow results for me on Fedora 33

[Alexander Browne (elcste)]

On my test computer at least, today's snap revision 1373 seems to have solved it.

Running `snap run --trace-exec chromium` on a cold boot I get

Slowest 10 exec calls during snap run:
  0.237s snap-update-ns
  0.400s /usr/lib/snapd/snap-confine
  0.087s /snap/chromium/1373/snap/command-chain/snapcraft-runner
  0.590s /snap/chromium/1373/bin/desktop-launch
  0.065s /usr/bin/snapctl
  0.114s /snap/chromium/1373/bin/chromium.launcher
  0.159s /usr/bin/dbus-send
  0.286s /usr/bin/xdg-settings
  3.609s /proc/self/exe
  5.238s /snap/chromium/1373/usr/lib/chromium-browser/chrome
Total time: 6.515s

[Olivier Tilloy (osomon)]

That's very good news, although there is no fonts-specific change/fix in that revision.
That revision uses LZO compression, which trades snap size (from ~172MB to 252MB) for startup speed. I'm glad this improves the situation so significantly! I am also working on a specific fix for font cache generation (using the gnome-3-28 snapcraft extension to build the snap), so I'll keep this bug open to track progress on this.

[Nathan Teodosio (nteodosio)]

This seems not to be an issue any more. Feel free to reset the status if otherwise.