Subject: 26.3; emacs uses 100% CPU with auto-revert-mode
From: Peter Ludemann <[email-masked]>
To: [email-masked]
Date: Mon, 16 Dec 2019 17:23:30 -0800
List-Id: <debbugs-submit.debbugs.gnu.org>

This problem occurs with emacs 26.3 but didn't occur with 25.x.
Possibly related to bug#33194.

My hypothesis is that emacs is monitoring some files that it shouldn't
but I need some help in figuring out which files are being monitored and
whether that is indeed a bug.

When I run a CPU-bound job that also does quite a bit of I/O, emacs
becomes very unresponsive -- running "top", I see CPU usage for emacs go
into the 50-100% range.
(Ubuntu 18.04, emacs 26.3 on a 4-CPU machine with SSD disk)

The job I'm running is
    parallel -v --will-cite --keep-order --group -L80 -j8
(the problem does not go away when I change to "-j3")

As far as I know, I don't have any of the output files or directories
open (I have global-auto-revert-mode set) -- all the outputs go into one
directory and when I search the Buffer List, I don't see that
directory.

I upgraded from emacs 25.3 to 26.3 today, with the same .emacs.desktop,
and the problem wasn't showing with emacs 25.3.

I double-checked the output of lsof on one of the running CPU processes
and again couldn't find anything that matched with the Emacs
buffer. However, I did notice that file-name-history did match some.

Any suggestions on how to track down what's causing the polling?  As I
mentioned, this didn't happen with emacs 25.3 with the same files
open. It also doesn't happen when I start 26.3 without the
.emacs.desktop (that is, with nothing in the Buffer List).

"strace -c" emacs when not running the CPU/IO job:
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 31.63    0.009027           3      2950      2534 recvmsg
 23.19    0.006618           3      2057           poll
 13.38    0.003819           3      1100           rt_sigprocmask
 12.10    0.003454          17       209           pselect6
  9.17    0.002618           6       466           writev
  7.62    0.002174           5       405           rt_sigreturn
  1.21    0.000344          57         6           openat
  0.37    0.000105           4        30         1 read
  0.31    0.000089           3        26           timerfd_settime
  0.28    0.000080          11         7           ioctl
  0.22    0.000064          64         1           vfork
  0.11    0.000032          11         3           fcntl
  0.11    0.000030           4         8           close
  0.09    0.000026           1        51         9 stat
  0.06    0.000017          17         1           pipe2
  0.06    0.000016           0        48        11 faccessat
  0.04    0.000011          11         1           getuid
  0.03    0.000009           5         2           wait4
  0.01    0.000003           1         4           write
  0.00    0.000000           0         3           fstat
  0.00    0.000000           0         3           lseek
  0.00    0.000000           0         1           inotify_add_watch
  0.00    0.000000           0         1         1 readlinkat
------ ----------- ----------- --------- --------- ----------------
100.00    0.028536                  7383      2556 total

"strace -c" emacs when running the CPU/IO job:
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 30.79    0.013978           1     15384           poll
 21.05    0.009554           1     15799     12395 recvmsg
 19.44    0.008827           1      6538           writev
 13.96    0.006339           1     12446           rt_sigprocmask
  6.97    0.003162           2      1554           pselect6
  2.96    0.001342           0      3108           rt_sigreturn
  2.95    0.001338           1      1551           read
  1.88    0.000855           1      1551           ioctl
  0.00    0.000000           0        10           stat
  0.00    0.000000           0         1           restart_syscall
  0.00    0.000000           0        10           faccessat
------ ----------- ----------- --------- --------- ----------------
100.00    0.045395                 57952     12395 total

"strace -c emacs when running the CPU/IO job without
global-auto-revert-mode:

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 37.41    0.001833           1      1860      1576 recvmsg
 27.88    0.001366           1      1619           poll
 14.78    0.000724           5       142           pselect6
  7.43    0.000364           2       201           writev
  6.29    0.000308           1       570           rt_sigprocmask
  6.06    0.000297           1       318        24 rt_sigreturn
  0.08    0.000004           1         6           write
  0.06    0.000003           0         8           read
  0.02    0.000001           1         2           openat
  0.00    0.000000           0         2           close
  0.00    0.000000           0         6         3 recvfrom
  0.00    0.000000           0         1         1 faccessat
------ ----------- ----------- --------- --------- ----------------
100.00    0.004900                  4735      1604 total

In GNU Emacs 26.3 (build 2, x86_64-pc-linux-gnu, GTK+ Version 3.22.30)
 of 2019-09-16 built on lcy01-amd64-030
Windowing system distributor 'The X.Org Foundation', version 11.0.11906000
System Description: Ubuntu 18.04.3 LTS

Recent messages:
Making completion list...
Saving file /tmp/t10.kythe.json-decoded...
Wrote /tmp/t10.kythe.json-decoded
Quit [5 times]
command-execute: Buffer is read-only: #<buffer *Help*>
Mark set
Quit
Mark saved where search started
Quit [2 times]
Mark saved where search started [2 times]
Quit [4 times]
Configured using:
 'configure --build=x86_64-linux-gnu --prefix=/usr
 '--includedir=${prefix}/include' '--mandir=${prefix}/share/man'
 '--infodir=${prefix}/share/info' --sysconfdir=/etc --localstatedir=/var
 --disable-silent-rules '--libdir=${prefix}/lib/x86_64-linux-gnu'
 '--libexecdir=${prefix}/lib/x86_64-linux-gnu' --disable-maintainer-mode
 --disable-dependency-tracking --prefix=/usr --sharedstatedir=/var/lib
 --program-suffix=26 --with-modules --with-file-notification=inotify
 --with-mailutils --with-x=yes --with-x-toolkit=gtk3 --with-xwidgets
 --with-lcms2 'CFLAGS=-g -O2
 -fdebug-prefix-map=/build/emacs26-TP6iDo/emacs26-26.3~1.git96dd019=.
-fstack-protector-strong
 -Wformat -Werror=format-security -no-pie' 'CPPFLAGS=-Wdate-time
 -D_FORTIFY_SOURCE=2' 'LDFLAGS=-Wl,-Bsymbolic-functions -Wl,-z,relro
 -no-pie''

Configured features:
XPM JPEG TIFF GIF PNG RSVG IMAGEMAGICK SOUND GPM DBUS GSETTINGS GLIB
NOTIFY LIBSELINUX GNUTLS LIBXML2 FREETYPE M17N_FLT LIBOTF XFT ZLIB
TOOLKIT_SCROLL_BARS GTK3 X11 XDBE XIM MODULES THREADS XWIDGETS
LIBSYSTEMD LCMS2

Important settings:
  value of $LC_MONETARY: en_CA.UTF-8
  value of $LC_NUMERIC: en_CA.UTF-8
  value of $LC_TIME: en_CA.UTF-8
  value of $LANG: en_US.UTF-8
  value of $XMODIFIERS: @im=ibus
  locale-coding-system: utf-8-unix

Major mode: GNUmakefile

Minor modes in effect:
  shell-dirtrack-mode: t
  diff-auto-refine-mode: t
  global-auto-revert-mode: t
  show-paren-mode: t
  display-time-mode: t
  savehist-mode: t
  desktop-save-mode: t
  cl-old-struct-compat-mode: t
  tooltip-mode: t
  global-eldoc-mode: t
  electric-indent-mode: t
  mouse-wheel-mode: t
  menu-bar-mode: t
  file-name-shadow-mode: t
  global-font-lock-mode: t
  font-lock-mode: t
  auto-composition-mode: t
  auto-encryption-mode: t
  auto-compression-mode: t
  column-number-mode: t
  line-number-mode: t
  transient-mark-mode: t

Load-path shadows:
/usr/share/emacs/site-lisp/llvm-6.0/llvm-mode hides
/usr/share/emacs/site-lisp/llvm-7/llvm-mode
/usr/share/emacs/site-lisp/llvm-6.0/emacs hides
/usr/share/emacs/site-lisp/llvm-7/emacs
/usr/share/emacs/site-lisp/llvm-6.0/tablegen-mode hides
/usr/share/emacs/site-lisp/llvm-7/tablegen-mode
/home/peter/.emacs.d/elpa/go-mode-1.5.0/go-mode hides
/usr/share/emacs/site-lisp/elpa-src/go-mode-1.5.0/go-mode
/home/peter/.emacs.d/elpa/go-mode-1.5.0/go-mode-autoloads hides
/usr/share/emacs/site-lisp/elpa-src/go-mode-1.5.0/go-mode-autoloads
/home/peter/.emacs.d/elpa/go-mode-1.5.0/go-mode-pkg hides
/usr/share/emacs/site-lisp/elpa-src/go-mode-1.5.0/go-mode-pkg
/usr/share/emacs/site-lisp/dictionaries-common/flyspell hides
/usr/share/emacs/26.3/lisp/textmodes/flyspell
/usr/share/emacs/site-lisp/dictionaries-common/ispell hides
/usr/share/emacs/26.3/lisp/textmodes/ispell
/usr/share/emacs/site-lisp/rst hides
/usr/share/emacs/26.3/lisp/textmodes/rst
~/emacs/prolog hides /usr/share/emacs/26.3/lisp/progmodes/prolog
/usr/share/emacs/site-lisp/latex-cjk-thai/thai-word hides
/usr/share/emacs/26.3/lisp/language/thai-word

Features:
(shadow mail-extr emacsbug sendmail eieio-opt speedbar sb-image ezimage
dframe find-func completion help-fns tabify man novice pulse misearch
multi-isearch solarized dash quail inf-haskell haskell-decl-scan haskell
haskell-completions haskell-load haskell-commands highlight-uses-mode
haskell-modules haskell-sandbox haskell-repl haskell-debug
haskell-interactive-mode haskell-presentation-mode haskell-collapse
haskell-navigate-imports haskell-compile haskell-process haskell-session
haskell-hoogle edmacro kmacro sort autoload radix-tree cl-extra lisp-mnt
help-mode mm-archive network-stream starttls url-http tls gnutls url-gw
nsm url-cache url-auth vc vc-dispatcher server erlang tempo cl perl-mode
asm-mode conf-mode jka-compr add-log rst haskell-mode haskell-cabal
haskell-utils haskell-font-lock haskell-indentation haskell-string
haskell-sort-imports haskell-lexeme rx haskell-align-imports
haskell-compat haskell-complete-module haskell-ghc-support flymake-proc
flymake warnings dabbrev haskell-customize go-mode url url-proxy
url-privacy url-expand url-methods url-history url-cookie url-domsuf
url-util mailcap find-file ffap etags xref project sh-script executable
tar-mode markdown-mode noutline outline message rmc puny rfc822 mml
mml-sec epa derived epg gnus-util rmail rmail-loaddefs mm-decode
mm-bodies mm-encode mail-parse rfc2231 rfc2047 rfc2045 mm-util
ietf-drums mail-prsvr mailabbrev mail-utils gmm-utils mailheader
elec-pair mhtml-mode css-mode smie color dired dired-loaddefs make-mode
python tramp-sh tramp tramp-compat tramp-loaddefs trampver ucs-normalize
parse-time format-spec smerge-mode prolog align shell pcomplete vc-git
diff-mode easy-mmode js advice sgml-mode dom json map imenu thingatpt
cc-mode cc-fonts cc-guess cc-menus cc-cmds cc-styles cc-align cc-engine
cc-vars cc-defs finder-inf info package easymenu epg-config url-handlers
url-parse auth-source cl-seq eieio eieio-core cl-macs eieio-loaddefs
password-cache url-vars seq byte-opt gv bytecomp byte-compile cconv
autorevert filenotify grep compile comint ansi-color ring cus-start
cus-load time-date paren time savehist desktop frameset cl-loaddefs
cl-lib mule-util tooltip eldoc electric uniquify ediff-hook vc-hooks
lisp-float-type mwheel term/x-win x-win term/common-win x-dnd tool-bar
dnd fontset image regexp-opt fringe tabulated-list replace newcomment
text-mode elisp-mode lisp-mode prog-mode register page menu-bar
rfn-eshadow isearch timer select scroll-bar mouse jit-lock font-lock
syntax facemenu font-core term/tty-colors frame cl-generic cham georgian
utf-8-lang misc-lang vietnamese tibetan thai tai-viet lao korean
japanese eucjp-ms cp51932 hebrew greek romanian slovak czech european
ethiopic indian cyrillic chinese composite charscript charprop
case-table epa-hook jka-cmpr-hook help simple abbrev obarray minibuffer
cl-preloaded nadvice loaddefs button faces cus-face macroexp files
text-properties overlay sha1 md5 base64 format env code-pages mule
custom widget hashtable-print-readable backquote threads dbusbind
inotify lcms2 dynamic-setting system-font-setting font-render-setting
xwidget-internal move-toolbar gtk x-toolkit x multi-tty
make-network-process emacs)

Memory information:
((conses 16 791439 152674)
 (symbols 48 44537 1)
 (miscs 40 2000 2396)
 (strings 32 134121 30613)
 (string-bytes 1 6691533)
 (vectors 16 70253)
 (vector-slots 8 1997947 168512)
 (floats 8 365 431)
 (intervals 56 50166 2906)
 (buffers 992 501))