How to diagnose emacs running at 100% cpu

Question

I'm having a problem where occassionally emacs will run at 100% cpu, and just hang forever.

I've attached gdb to the process, and this is the stacktrace:

#0  0x00007fc210e5c5bb in pthread_sigmask () from /lib64/libpthread.so.0
#1  0x00000000005f5f95 in really_call_select ()
#2  0x00000000005f6d5d in thread_select ()
#3  0x00000000005d0fd7 in wait_reading_process_output ()
#4  0x00000000004f819e in wait_for_property_change ()
#5  0x00000000004fad93 in x_handle_selection_event ()
#6  0x0000000000515a10 in process_special_events ()
#7  0x0000000000516431 in swallow_events ()
#8  0x0000000000435a46 in sit_for ()
#9  0x000000000051c4cd in read_char ()
#10 0x000000000051c8a5 in read_key_sequence ()
#11 0x000000000051dfdc in command_loop_1 ()
#12 0x000000000058bec7 in internal_condition_case ()
#13 0x000000000050eef4 in command_loop_2 ()
#14 0x000000000058be09 in internal_catch ()
#15 0x000000000050ee93 in command_loop ()
#16 0x000000000051447a in recursive_edit_1 ()
#17 0x00000000005147b6 in Frecursive_edit ()
#18 0x000000000042c564 in main ()

Running strace -f I get the following:

strace: Process 2689 attached with 4 threads
[pid  2692] restart_syscall(<... resuming interrupted read ...> <unfinished ...>
[pid  2691] restart_syscall(<... resuming interrupted read ...> <unfinished ...>
[pid  2689] rt_sigprocmask(SIG_SETMASK, [],  <unfinished ...>
[pid  2693] restart_syscall(<... resuming interrupted read ...> <unfinished ...>
[pid  2689] <... rt_sigprocmask resumed>NULL, 8) = 0
[pid  2689] pselect6(18, [3 6 13 17], NULL, NULL, {tv_sec=0, tv_nsec=0}, {NULL, 8}) = 1 (in [3], left {tv_sec=0, tv_nsec=0})
[pid  2689] rt_sigprocmask(SIG_BLOCK, [INT], [], 8) = 0
[pid  2689] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid  2689] rt_sigprocmask(SIG_BLOCK, [INT], [], 8) = 0
[pid  2689] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid  2689] pselect6(18, [3 6 13 17], NULL, NULL, {tv_sec=0, tv_nsec=0}, {NULL, 8}) = 1 (in [3], left {tv_sec=0, tv_nsec=0})
[pid  2689] rt_sigprocmask(SIG_BLOCK, [INT], [], 8) = 0
[pid  2689] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid  2689] rt_sigprocmask(SIG_BLOCK, [INT], [], 8) = 0
[pid  2689] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid  2689] pselect6(18, [3 6 13 17], NULL, NULL, {tv_sec=0, tv_nsec=0}, {NULL, 8}) = 1 (in [3], left {tv_sec=0, tv_nsec=0})
[pid  2689] rt_sigprocmask(SIG_BLOCK, [INT], [], 8) = 0
[pid  2689] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid  2689] rt_sigprocmask(SIG_BLOCK, [INT], [], 8) = 0
[pid  2689] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid  2689] pselect6(18, [3 6 13 17], NULL, NULL, {tv_sec=0, tv_nsec=0}, {NULL, 8}) = 1 (in [3], left {tv_sec=0, tv_nsec=0})

and it just continues in the select loop forever.

These are the 4 listed file descriptors

emacs   2689 steve    3u  a_inode               0,14         0     11756 [timerfd]
emacs   2689 steve    6u     unix 0x0000000098aa0ced       0t0     18247 type=STREAM
emacs   2689 steve   13u     unix 0x00000000db5acbc0       0t0     18252 type=STREAM
emacs   2689 steve   17r  a_inode               0,14         0     11756 inotify

That's as far as I can get.

Any ideas on how to diagnose what is happening here?

---

Edit:

It happened again, with slightly different stacktrace and strace results.

Here is the stacktrace from gdb:

#0  0x000000000050b847 in process_special_events ()
#1  0x000000000050c2c1 in swallow_events ()
#2  0x00000000005ce14a in wait_reading_process_output ()
#3  0x00000000004eb806 in x_get_foreign_selection ()
#4  0x0000000000580dec in Ffuncall ()
#5  0x00000000005c207c in exec_byte_code ()
#6  0x0000000000580d7b in Ffuncall ()
#7  0x00000000005829a2 in Fapply ()
#8  0x0000000000580dec in Ffuncall ()
#9  0x00000000005c207c in exec_byte_code ()
#10 0x0000000000580d7b in Ffuncall ()
#11 0x00000000005c207c in exec_byte_code ()
#12 0x0000000000580d7b in Ffuncall ()

and the strace output:

strace: Process 22077 attached with 4 threads
[pid 22081] restart_syscall(<... resuming interrupted read ...> <unfinished ...>
[pid 22079] restart_syscall(<... resuming interrupted read ...> <unfinished ...>
[pid 22080] restart_syscall(<... resuming interrupted read ...> <unfinished ...>
[pid 22077] brk(NULL)                   = 0xa39e6000
[pid 22077] brk(0xa3a08000)             = 0xa3a08000
[pid 22077] brk(NULL)                   = 0xa3a08000
[pid 22077] brk(0xa3a2a000)             = 0xa3a2a000
[pid 22077] brk(NULL)                   = 0xa3a2a000
[pid 22077] brk(0xa3a4c000)             = 0xa3a4c000
[pid 22077] brk(NULL)                   = 0xa3a4c000
[pid 22077] brk(0xa3a6e000)             = 0xa3a6e000
[pid 22077] brk(NULL)                   = 0xa3a6e000
[pid 22077] brk(0xa3a90000)             = 0xa3a90000
[pid 22077] brk(NULL)                   = 0xa3a90000
[pid 22077] brk(0xa3ab2000)             = 0xa3ab2000

brk just continues forever... until suddenly, after several minutes, it comes back

[pid 22077] brk(NULL)                   = 0xb2450000
[pid 22077] brk(0xb2472000)             = 0xb2472000
[pid 22077] brk(NULL)                   = 0xb2472000
[pid 22077] brk(0xb2494000)             = 0xb2494000
[pid 22077] --- SIGIO {si_signo=SIGIO, si_code=SI_KERNEL} ---
[pid 22077] rt_sigreturn({mask=[]})     = 64
[pid 22077] recvmsg(6, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="X\2%8\342\345\223\0\3\24\4\0\20\0\0\0\0\0\0\24\24\24\24\24\0\0\3\37%\2\0\0", iov_len=4096}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 32
[pid 22077] recvmsg(6, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 22077] poll([{fd=6, events=POLLIN}, {fd=7, events=POLLIN}, {fd=8, events=POLLIN}], 3, 0) = 0 (Timeout)
[pid 22077] poll([{fd=6, events=POLLIN}, {fd=7, events=POLLIN}, {fd=8, events=POLLIN}], 3, 0) = 0 (Timeout)
[pid 22077] recvmsg(6, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
[pid 22077] poll([{fd=6, events=POLLIN}, {fd=7, events=POLLIN}, {fd=8, events=POLLIN}], 3, 0) = 0 (Timeout)

and emacs' usage drops back down to idle.

---

Resolution?

I found a few threads referencing the X11 clipboard being the cause of hangs.

I added (setq select-enable-clipboard nil) to my init.el, and have not had a hang since.

Can anyone explain what is causing this, and whether there is a better resolution?

Answer 1

Well, just from the brk calls it looks like it allocated about 230 megs, which is on the large side for the clipboard. Maybe whatever was in the clipboard at the time really was that large, or maybe Emacs failed to parse it correctly and ran away for a bit.

If you want to figure out what the problem really is, you either need to find a reliable way to reproduce it, or you need to make a reproducible recording of the problem as it happens. You can probably use rr (rr-project.org) to make the recording. Once you have the recording, you can replay it as often as is required in order to understand what was going on. rr is light-weight enough that you can even record your ordinary Emacs sessions until you see the problem, then go back to using Emacs with select-enable-clipboard unset.