Slow startup time for mqtt-explorer with --trace-exec data

1

Heya, snapd peeps. I installed mqtt-explorer, and on starting it up nothing happened and I thought it was broken, so I started it again; same thing, tried again… until two minutes later, five MQTT Explorer windows appeared on my desktop. Startup time for this appears to be somewhere around two minutes. I mean, gosh. @popey mentioned the new --trace-exec option to snap run, and how it’s important to have data on slow startups so they can be fixed, so here is some.

I snap removed mqtt-explorer so that I’d have a “clean cache”, and then snap installed it.

First run:

$ snap run --trace-exec mqtt-explorer
Gtk-Message: Failed to load module "appmenu-gtk-module"
Gtk-Message: Failed to load module "canberra-gtk-module"
Gtk-Message: Failed to load module "canberra-gtk-module"
Gtk-Message: Failed to load module "topmenu-gtk-module"
subscribing app/update/check
[11:39:26.517] [info] App starting...
subscribing connection/add/mqtt
subscribing connection/remove
subscribing storage/store
subscribing storage/load
subscribing storage/clear
icon path /snap/mqtt-explorer/9/resources/app.asar/dist/src/icon.png
Slowest 10 exec calls during snap run:
  0.196s /snap/core/6405/usr/lib/snapd/snap-confine
  0.044s /snap/mqtt-explorer/9/command.sh
  0.029s /usr/bin/head
  0.184s /snap/mqtt-explorer/9/usr/lib/x86_64-linux-gnu/glib-2.0/gio-querymodules
  0.223s /snap/mqtt-explorer/9/usr/lib/x86_64-linux-gnu/gdk-pixbuf-2.0/gdk-pixbuf-query-loaders
  0.271s /snap/mqtt-explorer/9/usr/lib/x86_64-linux-gnu/libgtk-3-0/gtk-query-immodules-3.0
  1.470s /snap/mqtt-explorer/9/bin/desktop-launch
  0.207s /proc/self/exe
  138.047s /snap/mqtt-explorer/9/mqtt-explorer
  135.346s /proc/self/exe
Total time: 139.869s

Second run was approximately the same, suggesting that this is not just about one-time generation of cached data:

$ snap run --trace-exec mqtt-explorer
Gtk-Message: Failed to load module "appmenu-gtk-module"
Gtk-Message: Failed to load module "canberra-gtk-module"
Gtk-Message: Failed to load module "canberra-gtk-module"
Gtk-Message: Failed to load module "topmenu-gtk-module"
subscribing app/update/check
[11:45:04.911] [info] App starting...
subscribing connection/add/mqtt
subscribing connection/remove
subscribing storage/store
subscribing storage/load
subscribing storage/clear
icon path /snap/mqtt-explorer/9/resources/app.asar/dist/src/icon.png
Slowest 10 exec calls during snap run:
  0.012s snap-update-ns
  0.106s /snap/core/6405/usr/lib/snapd/snap-confine
  0.009s /bin/mkdir
  0.011s /usr/bin/head
  0.009s /usr/bin/head
  0.015s /bin/mv
  0.299s /snap/mqtt-explorer/9/bin/desktop-launch
  0.090s /proc/self/exe
  136.274s /snap/mqtt-explorer/9/mqtt-explorer
  135.646s /proc/self/exe
2

This is my run on kubuntu 18.04, after a fresh install and removing ~/snap/mqtt-explorer.

$ snap run --trace-exec mqtt-explorer
subscribing app/update/check
[12:07:46.322] [info] App starting...
subscribing connection/add/mqtt
subscribing connection/remove
subscribing storage/store
subscribing storage/load
subscribing storage/clear
icon path /snap/mqtt-explorer/9/resources/app.asar/dist/src/icon.png
Slowest 10 exec calls during snap run:
  0.250s /snap/core/6405/usr/lib/snapd/snap-confine
  0.031s /usr/bin/head
  0.190s /snap/mqtt-explorer/9/usr/lib/x86_64-linux-gnu/glib-2.0/gio-querymodules
  0.026s /snap/mqtt-explorer/9/usr/lib/x86_64-linux-gnu/glib-2.0/glib-compile-schemas
  0.287s /snap/mqtt-explorer/9/usr/lib/x86_64-linux-gnu/gdk-pixbuf-2.0/gdk-pixbuf-query-loaders
  0.288s /snap/mqtt-explorer/9/usr/lib/x86_64-linux-gnu/libgtk-3-0/gtk-query-immodules-3.0
  1.551s /snap/mqtt-explorer/9/bin/desktop-launch
  0.284s /proc/self/exe
  8.843s /snap/mqtt-explorer/9/mqtt-explorer
  4.970s /proc/self/exe
Total time: 10.730s
1 Like
3

From a quick try of this, /snap/mqtt-explorer/9/mqtt-explorer seems to measure how long the app has been open, rather than how long it takes to open in the first place. Disregard that line and you’re possible looking at a couple of seconds?

4

FWIW:

subscribing app/update/check
[20:03:33.175] [info] App starting...
subscribing connection/add/mqtt
subscribing connection/remove
subscribing storage/store
subscribing storage/load
subscribing storage/clear
icon path /snap/mqtt-explorer/9/resources/app.asar/dist/src/icon.png
Slowest 10 exec calls during snap run:
  0.120s /snap/core/6405/usr/lib/snapd/snap-confine
  0.026s /snap/mqtt-explorer/9/usr/lib/x86_64-linux-gnu/glib-2.0/gio-querymodules
  0.015s /bin/ls
  0.015s /bin/ls
  0.024s /snap/mqtt-explorer/9/usr/lib/x86_64-linux-gnu/glib-2.0/glib-compile-schemas
  0.052s /snap/mqtt-explorer/9/usr/lib/x86_64-linux-gnu/gdk-pixbuf-2.0/gdk-pixbuf-query-loaders
  0.064s /snap/mqtt-explorer/9/usr/lib/x86_64-linux-gnu/libgtk-3-0/gtk-query-immodules-3.0
  1.178s /snap/mqtt-explorer/9/bin/desktop-launch
  5.274s /snap/mqtt-explorer/9/mqtt-explorer
  4.514s /proc/self/exe
Total time: 6.732s
5

Might also be useful to do a full strace with timestamps -t to see what it’s spending time doing.

snap run --strace='-e trace=stat,open,read,mmap -t' mqtt-explorer 2>&1 | tee strace.log

6

Sadly, no. It’s two minutes before the window shows up.

I have straced it as suggested. I won’t paste the whole log here because it’s 2.5MB. But it seems to be broken up as follows:

20:29:44 log starts
(lots and lots and lots of strace lines, reading files and so on, which is expected)
20:29:46 (two seconds later) the “lots of lines” seem to finish
we then do this, and pretty much nothing but this:

[pid 23546] 20:29:46 read(13, “!”, 2) = 1
[pid 23674] 20:29:46 read(25, “\0”, 1) = 1

four times a second, every second, for the next two minutes (!)

then
20:31:57 (130 seconds later) lots of lines again, as something seems to be happening
and this is when the window shows up.

So, whatever those two lines above are doing, that’s what’s taking the time. I’m happy to take additional logs and provide them if someone tells me what to run.

1 Like