bug#38644: 26.3; emacs uses 100% CPU with auto-revert-mode

[Michael Albinus]

Peter Ludemann <peter.ludemann@gmail.com> writes:

Hi Peter,

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

That's a good catch.

> 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")

You are reading commands from STDIN? Which?

> 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.

It might be the default directory of a buffer not bound to a file.

> 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.

In bug#33194, a patch for Emacs 27.0.50 is mentioned. Do you have a
chance to run this for test?

> 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).

Could you show the contents of .emacs.desktop?

What happens if you set auto-revert-use-notify to nil?

What's the value of (pp file-notify-descriptors) ?

What do you see, if you remove the comment of the message call in
file-notify-handle-event (lisp/filenotify.el, line 93)?

> "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

inotify_add_watch is an indication, that file notifications are in
place.

Best regards, Michael.