Debugging a slow thumbnailer process

I am trying a debug a peculiar performance behavior in the thumbnail-generating process for [eog](https://wiki.gnome.org/Apps/EyeOfGnome) , specifically [gdk-pixbuf](https://developer.gnome.org/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](https://github.com/nbeaver/gdk-pixbuf-bug/blob/master/strace_1564026245.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 22:44:05 openat(AT_FDCWD, "/usr/share/fonts/opentype/noto/NotoSansCJK-Bold.ttc", O_RDONLY) = 5 22:44:05 fcntl(5, F_SETFD, FD_CLOEXEC) = 0 22:44:05 fstat(5, {st_mode=S_IFREG|0644, st_size=20930832, ...}) = 0 22:44:05 mmap(NULL, 20930832, PROT_READ, MAP_PRIVATE, 5, 0) = 0x7fd491988000 22:44:05 close(5) = 0 22:44:06 munmap(0x7fd491988000, 20930832) = 0 22:44:06 openat(AT_FDCWD, "/usr/share/fonts/opentype/noto/NotoSansCJK-Bold.ttc", O_RDONLY) = 5 22:44:06 fcntl(5, F_SETFD, FD_CLOEXEC) = 0 22:44:06 fstat(5, {st_mode=S_IFREG|0644, st_size=20930832, ...}) = 0 22:44:06 mmap(NULL, 20930832, PROT_READ, MAP_PRIVATE, 5, 0) = 0x7fd491988000 22:44:06 close(5) = 0 22:44:31 stat("/usr/share/fonts/opentype/stix-word/STIXMath-Regular.otf", {st_mode=S_IFREG|0644, st_size=476872, ...}) = 0 22:44:31 openat(AT_FDCWD, "/usr/share/fonts/opentype/stix-word/STIXMath-Regular.otf", O_RDONLY) = 5 22:44:31 fcntl(5, F_SETFD, FD_CLOEXEC) = 0 22:44:31 fstat(5, {st_mode=S_IFREG|0644, st_size=476872, ...}) = 0 22:44:31 mmap(NULL, 476872, PROT_READ, MAP_PRIVATE, 5, 0) = 0x7fd49c26a000 22:44:31 close(5) = 0 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](https://github.com/nbeaver/gdk-pixbuf-bug/blob/master/strace_1564026245.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: 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?