Running some apps in background triggers 5 or 10 second hang before they start

English Applications
#1

This just started happening to me recently on Leap 15. But it wasn’t happening before, and I’m unsure what caused it to start.

Running X applications in the “foreground” from a shell (in a konsole, xterm, etc. window) results in the X window for the applications immediately displaying as they’re supposed to.

However, when I run certain X applications (e.g. emacs, xemacs, gkrellm, etc.) in the “background” from a shell, then I get a hang of exactly 10 seconds. For example: “emacs &” (without quotes). During this hang while I wait for the X window to appear, that shell is completely frozen. I can’t do anything with it at all (e.g. Ctl-C). However, I can type freely in a shell window in another tab in the same window. So it seems to be something relating to the shell that’s holding up the application.

Digging a bit deeper, I decided to run “strace -r app &” to see if I could get any clues. Here’s an excerpt of what I see when I run “strace -r emacs &”:


...
     0.000045 mprotect(0x5618e68fc000, 8192, PROT_READ) = 0
     0.000016 mprotect(0x7fab743a1000, 4096, PROT_READ) = 0
     0.000014 munmap(0x7fab74364000, 248226) = 0
     0.000038 openat(AT_FDCWD, "/dev/tty", O_RDWR|O_NONBLOCK) = -1 EBUSY (Device or resource busy)
     5.116922 ioctl(0, TCGETS, {B38400 opost isig -icanon -echo ...}) = 0
     0.000102 fstat(0, {st_mode=S_IFCHR|0600, st_rdev=makedev(136, 3), ...}) = 0
     0.000139 brk(NULL)                 = 0x5618e83f0000
     0.000064 brk(0x5618e8411000)       = 0x5618e8411000
     0.000021 readlink("/proc/self/fd/0", "/dev/pts/3", 4095) = 10
     0.000031 stat("/dev/pts/3", {st_mode=S_IFCHR|0600, st_rdev=makedev(136, 3), ...}) = 0
     0.000020 openat(AT_FDCWD, "/dev/pts/3", O_RDWR|O_NONBLOCK) = -1 EBUSY (Device or resource busy)
     5.119610 stat("/usr/lib/locale/locale-archive", 0x7fffd7f39900) = -1 ENOENT (No such file or directory)
 ...

Notice the 2 calls that take 5 seconds each. It looks like it might be hanging while trying to open “/dev/tty” and “/dev/pts/3”.

However, when I do an “strace emacs” without putting this in the background, then the open of “/dev/tty” succeeds immediately and it never tries to open /dev/pts/…

Does anyone have any ideas as to what’s going on here? Or what I can do to try and fix it? --Thanks.

#2

Another X app that exhibits this hang-when-run-background is gkrellm. Here’s an excerpt of the output of “strace -r gkrellm &”:


...
     0.000014 rt_sigaction(SIGINT, {sa_handler=SIG_IGN, sa_mask=], sa_flags=SA_RESTORER, sa_restorer=0x7f97c2a8d160}, {sa_handler=SIG_DFL, sa_mask=], sa_flags=0}, 8) = 0
     0.000016 rt_sigaction(SIGQUIT, {sa_handler=SIG_IGN, sa_mask=], sa_flags=SA_RESTORER, sa_restorer=0x7f97c2a8d160}, {sa_handler=SIG_DFL, sa_mask=], sa_flags=0}, 8) = 0
     0.000013 rt_sigprocmask(SIG_BLOCK, [CHLD], ], 8) = 0
     0.000014 clone(child_stack=NULL, flags=CLONE_PARENT_SETTID|SIGCHLD, parent_tidptr=0x7ffce22240ec) = 31103
     0.000254 **wait4(31103, {WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 31103**
    **10.259755** rt_sigaction(SIGINT, {sa_handler=SIG_DFL, sa_mask=], sa_flags=SA_RESTORER, sa_restorer=0x7f97c2a8d160}, NULL, 8) = 0
     0.000090 rt_sigaction(SIGQUIT, {sa_handler=SIG_DFL, sa_mask=], sa_flags=SA_RESTORER, sa_restorer=0x7f97c2a8d160}, NULL, 8) = 0
     0.000087 rt_sigprocmask(SIG_SETMASK, ], NULL, 8) = 0
     0.000023 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=31103, si_uid=26374, si_status=0, si_utime=0, si_stime=0} ---
     0.000036 openat(AT_FDCWD, "/etc/fstab", O_RDONLY) = 6
...

Notice the 10 second hang where it waited for a child process to exit. That made me wonder whether this child process might be blocked on the same thing as emacs was.

Sure enough, “strace -r -f gkrellm &” confirms that it is:


...
[pid 31308]      0.000018 mprotect(0x7f0e14511000, 4096, PROT_READ) = 0
[pid 31308]      0.000020 munmap(0x7f0e144d4000, 248226) = 0
[pid 31308]      0.000048 **openat(AT_FDCWD, "/dev/tty", O_RDWR|O_NONBLOCK) = -1 EBUSY (Device or resource busy)**
[pid 31308]      **5.152202** ioctl(0, TCGETS, {B38400 opost isig -icanon -echo ...}) = 0
[pid 31308]      0.000076 fstat(0, {st_mode=S_IFCHR|0600, st_rdev=makedev(136, 3), ...}) = 0
[pid 31308]      0.000110 brk(NULL)     = 0x55a4798e4000
[pid 31308]      0.000042 brk(0x55a479905000) = 0x55a479905000
[pid 31308]      0.000027 readlink("/proc/self/fd/0", "/dev/pts/3", 4095) = 10
[pid 31308]      0.000039 stat("/dev/pts/3", {st_mode=S_IFCHR|0600, st_rdev=makedev(136, 3), ...}) = 0
[pid 31308]      0.000026 **openat(AT_FDCWD, "/dev/pts/3", O_RDWR|O_NONBLOCK) = -1 EBUSY (Device or resource busy)**
[pid 31308]      **5.119658** stat("/usr/lib/locale/locale-archive", 0x7ffc97a98aa0) = -1 ENOENT (No such file or directory)
...

Different X app. But same underlying symptoms causing the 10 second hang on startup – but only when I run it in the background. (???)

#3

What’s the output from

uname -a

It looks like this earlier thread
Poor responsiveness; slow window opening
and that was due to a kernel issue that should be fixed with today’s kernel update.

#4

Thanks, nrickert! I think you nailed it. That is probably the same issue I’m having as I was both 1) using tcsh and 2) running kernel 4.12.14-lp150.12.25-default as well:


Linux stealth 4.12.14-lp150.12.25-default #1 SMP Thu Nov 1 06:14:23 UTC 2018 (3fcf457) x86_64 x86_64 x86_64 GNU/Linux

After doing an Online Update (being careful “not” to spawn yast from a tcsh), I’m now running 4.12.14-lp150.12.28-default.

This update appears to have completely fixed the “10 second hang” problem.

strace now reveals that the openat of “/dev/tty” is now succeeding immediately rather than blocking for 5 or 10 seconds as before:


     0.000047 mprotect(0x55e894c4a000, 8192, PROT_READ) = 0
     0.000014 mprotect(0x7f5622daf000, 4096, PROT_READ) = 0
     0.000013 munmap(0x7f5622d72000, 248402) = 0
     0.000042 **openat(AT_FDCWD, "/dev/tty", O_RDWR|O_NONBLOCK) = 3**
     **0.000027** close(3)                  = 0
     0.000014 stat("/usr/lib/locale/locale-archive", 0x7fff4576a0a0) = -1 ENOENT (No such file or directory)
     0.000046 brk(NULL)                 = 0x55e8961d6000
     0.000014 brk(0x55e8961f7000)       = 0x55e8961f7000

Thanks again!

#5

I’m glad things are now working properly for you. And thanks for reporting back.