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
eogon a directory;there is a particular SVG in the directory that does not already have a thumbnail in
~/.cache/thumbnails/.(I use
touchto 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:
-fTrace 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:
-ffIf the
-o filenameoption is in effect, each processes trace is written tofilename.pidwherepidis 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 -fpicking up/usr/bin/gdk-pixbuf-thumbnaileras a child process ofeog?Does
eoguse an unusual method to create child processes?How can I use
gdbto attach to the/usr/bin/gdk-pixbuf-thumbnailerprocess and see what function it's spending time in?What might be causing this behavior?
