3

I am trying a debug a peculiar performance behavior in the thumbnail-generating process for eog, specifically gdk-pixbuf. The minimal files to reproduce are here:

https://github.com/nbeaver/gdk-pixbuf-bug

The process tree looks like this:

systemd,1 splash
  `-plasmashell,4366
      `-konsole,6783
          `-bash,6793
              `-make,6949 reproduce
                  `-eog,6973 /usr/share/doc/docutils-doc/docs/user/images
                      `-bwrap,10071 --ro-bind /usr /usr --ro-bind /bin /bin --ro-bind /lib64 /lib64 --ro-bind /lib /lib --ro-bind /sbin /sbin --proc /proc --dev /dev --chdir / --setenv GIO_USE_VFS local --unshare-all --die-with-parent --bind /tmp/gnome-desktop-thumbnailer-2HUN5Z /tmp --ro-bind /usr/share/doc/docutils-doc/docs/user/images/s5-files.svg /tmp/gnome-desktop-file-to-thumbnail.svg --seccomp 11 /usr/bin/gdk-pixbuf-thumbnailer -s 128 file:///tmp/gnome-desktop-file-to-thumbnail.svg /tmp/gnome-desktop-thumbnailer.png
                          `-bwrap,10074 --ro-bind /usr /usr --ro-bind /bin /bin --ro-bind /lib64 /lib64 --ro-bind /lib /lib --ro-bind /sbin /sbin --proc /proc --dev /dev --chdir / --setenv GIO_USE_VFS local --unshare-all --die-with-parent --bind /tmp/gnome-desktop-thumbnailer-2HUN5Z /tmp --ro-bind /usr/share/doc/docutils-doc/docs/user/images/s5-files.svg /tmp/gnome-desktop-file-to-thumbnail.svg --seccomp 11 /usr/bin/gdk-pixbuf-thumbnailer -s 128 file:///tmp/gnome-desktop-file-to-thumbnail.svg /tmp/gnome-desktop-thumbnailer.png
                              `-gdk-pixbuf-thum,10075 -s 128 file:///tmp/gnome-desktop-file-to-thumbnail.svg /tmp/gnome-desktop-thumbnailer.png

From the strace log, it looks like /usr/bin/gdk-pixbuf-thumbnailer is spending about 30 seconds looking at font files:

22:44:05 munmap(0x7fd491988000, 20930832) = 0 <0.000558>
22:44:05 openat(AT_FDCWD, "/usr/share/fonts/opentype/noto/NotoSansCJK-Bold.ttc", O_RDONLY) = 5 <0.000060>
22:44:05 fcntl(5, F_SETFD, FD_CLOEXEC)  = 0 <0.000014>
22:44:05 fstat(5, {st_mode=S_IFREG|0644, st_size=20930832, ...}) = 0 <0.000013>
22:44:05 mmap(NULL, 20930832, PROT_READ, MAP_PRIVATE, 5, 0) = 0x7fd491988000 <0.000021>
22:44:05 close(5)                       = 0 <0.000011>
22:44:06 munmap(0x7fd491988000, 20930832) = 0 <0.000525>
22:44:06 openat(AT_FDCWD, "/usr/share/fonts/opentype/noto/NotoSansCJK-Bold.ttc", O_RDONLY) = 5 <0.000076>
22:44:06 fcntl(5, F_SETFD, FD_CLOEXEC)  = 0 <0.000013>
22:44:06 fstat(5, {st_mode=S_IFREG|0644, st_size=20930832, ...}) = 0 <0.000012>
22:44:06 mmap(NULL, 20930832, PROT_READ, MAP_PRIVATE, 5, 0) = 0x7fd491988000 <0.000023>
22:44:06 close(5)                       = 0 <0.000013>
<snip>
22:44:31 stat("/usr/share/fonts/opentype/stix-word/STIXMath-Regular.otf", {st_mode=S_IFREG|0644, st_size=476872, ...}) = 0 <0.000024>
22:44:31 openat(AT_FDCWD, "/usr/share/fonts/opentype/stix-word/STIXMath-Regular.otf", O_RDONLY) = 5 <0.000026>
22:44:31 fcntl(5, F_SETFD, FD_CLOEXEC)  = 0 <0.000014>
22:44:31 fstat(5, {st_mode=S_IFREG|0644, st_size=476872, ...}) = 0 <0.000013>
22:44:31 mmap(NULL, 476872, PROT_READ, MAP_PRIVATE, 5, 0) = 0x7fd49c26a000 <0.000023>
22:44:31 close(5)                       = 0 <0.000015>

There is a particular SVG that triggers this behavior. However, it's not enough to just run eog or gdk-pixbuf-thumbnailer on the SVG. This behavior only happens when:

  • running eog on a directory;

  • there is a particular SVG in the directory that does not already have a thumbnail in ~/.cache/thumbnails/.

    (I use touch to update the timestamp of the SVG and make the thumbnailer run again every time.)

  • there is at least one other image in the same directory;

  • and the other image has a filename that collates before the SVG filename.

    (If the filename collates after the SVG filename, it generates the thumbnail in less than a second. Otherwise it takes around 30 seconds.)

There are some other puzzles, too. In the strace log, the wall clock times don't seem to match the time spent in the system calls. I've run eog under strace with the -f flag:

-f

Trace child processes as they are created by currently traced processes as a result of the fork(2), vfork(2) and clone(2) system calls.

and I've also tried the -ff flag:

-ff

If the -o filename option is in effect, each processes trace is written to filename.pid where pid is the numeric process id of each process.

but in either case gdk-pixbuf-thumbnailer doesn't show up in the logfiles of child processes.

I'm also having trouble running gdb on gdk-pixbuf-thumbnailer (something about "Target and debugger are in different PID namespaces"), so I can't tell where it's getting stuck.

$ sudo gdb -p 20789
[sudo] password for nathaniel:
<snip>
Error while mapping shared library sections:
Could not open `target:/lib/x86_64-linux-gnu/libbsd.so.0' as an executable file: No such file or directory

warning: Unable to find dynamic linker breakpoint function.
GDB will be unable to debug shared library initializers
and track explicitly loaded dynamic code.

warning: Target and debugger are in different PID namespaces; thread lists and other data are likely unreliable.  Connect to gdbserver inside the container.
(gdb) quit
Detaching from program: target:/newroot/usr/bin/gdk-pixbuf-thumbnailer, process 20789

I'm guessing this has to do with the bwrap container.

Version information:

$ apt-cache policy libgdk-pixbuf2.0-bin eog
libgdk-pixbuf2.0-bin:
  Installed: 2.36.11-2
  Candidate: 2.36.11-2
  Version table:
 *** 2.36.11-2 500
        500 http://us.archive.ubuntu.com/ubuntu bionic/main amd64 Packages
        100 /var/lib/dpkg/status
eog:
  Installed: 3.28.1-1
  Candidate: 3.28.1-1
  Version table:
 *** 3.28.1-1 500
        500 http://us.archive.ubuntu.com/ubuntu bionic/main amd64 Packages
        100 /var/lib/dpkg/status

My questions are:

  • Is this bug reproducible on other machines and other versions?

    (I happen to be using Ubuntu 18.04, but I want to know if this happens on other distributions.)

  • Why isn't strace -f picking up /usr/bin/gdk-pixbuf-thumbnailer as a child process of eog?

    Does eog use an unusual method to create child processes?

  • How can I use gdb to attach to the /usr/bin/gdk-pixbuf-thumbnailer process and see what function it's spending time in?

  • What might be causing this behavior?

1

After hitting upon the right combination of web search keywords, I am 90% sure this is a duplicate of this bug from December 15, 2018:

Slow thumbnail generation due to font issues

So I was investigating a slowdown in eog while auto-reloading SVG files, and it seems the problem was in the thumbnail generation, which was taking ~10s. (For a tiny SVG, mind you.) More specifically, gdk-pixbuf-thumbnailer complained about not finding a font config and spent a lot of time looking at fonts. Adding --ro-bind /var/cache/fontconfig /var/cache/fontconfig to the arguments for bwrap fixed the issue and the time is down to ~0.2s.

https://gitlab.gnome.org/GNOME/gnome-desktop/issues/90

It's mentioned here:

...and we have also the huge slowdown, see https://gitlab.gnome.org/GNOME/gnome-desktop/issues/90

https://bugs.launchpad.net/ubuntu/+source/gnome-desktop3/+bug/1795668

The fix is a patch in gnome-desktop3.

thumbnail: Fix slow thumbnailer due to missing font cache

On some distributions, the font cache doesn't live in /usr but in /var, which we don't allow access to when sandboxing the thumbnailers. Bind mount the fontconfig cache directory read-only if it lives outside /usr, to speed up thumbnailer startup.

https://gitlab.gnome.org/GNOME/gnome-desktop/merge_requests/25/diffs

It looks like the fix is in gnome-desktop3 version 3.30 and later, so as of July 19, 2019, that is only Ubuntu 19.10 (Eoan Ermine, unreleased) and 19.04 (Disco Dingo, end of life January 2020).

https://launchpad.net/ubuntu/+source/gnome-desktop3

https://launchpad.net/ubuntu/+source/gnome-desktop3/+publishinghistory

Version information for my machine:

$ apt-cache policy libgnome-desktop-3-17
libgnome-desktop-3-17:
  Installed: 3.28.2-0ubuntu1.5
  Candidate: 3.28.2-0ubuntu1.5
  Version table:
 *** 3.28.2-0ubuntu1.5 500
        500 http://us.archive.ubuntu.com/ubuntu bionic-updates/main amd64 Packages
        100 /var/lib/dpkg/status
     3.28.2-0ubuntu1.3 500
        500 http://security.ubuntu.com/ubuntu bionic-security/main amd64 Packages
     3.28.1-1ubuntu1 500
        500 http://us.archive.ubuntu.com/ubuntu bionic/main amd64 Packages

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.