bug#73855: [PATCH] * lisp/autorevert.el: Avoid reverting buffer in short time

bug#73855: [PATCH] * lisp/autorevert.el: Avoid reverting buffer in short time

[Lin Sun]

[-- Attachment #1: Type: text/plain, Size: 968 bytes --]

Hi,

High CPU consumption after enabling the "auto-revert" for a buffer.
Here is a way to reproduce the issue:
1. on one terminal run command "strace -f -o /tmp/a.log vi -nw"
2. on second terminal, start another emacs and open the file
/tmp/a.log, enable the "auto-revert" mode on the /tmp/a.log buffer.

Typing on 1st terminal(vi), the strace will continually write the
/tmp/a.log, and the emacs try to revert the /tmp/a.log buffer again
and again, then CPU loading turns high.

The function `auto-revert-handler` may be called twice for 2.5 seconds
intervals on a rapidly changed buffer/file.

The root cause is `auto-revert--end-lockout` will call
`auto-revert-handler` in which the `auto-revert--lockout-timer` was
cleared, then the next call `auto-revert-notify-handler` will revert
the buffer immediately regardless the buffer actually was revert just
before.

This patch will record when the buffer was reverted and avoid
reverting it again in the same second.

[-- Attachment #2: 0001-lisp-autorevert.el-Avoid-reverting-buffer-in-short-t.patch --]
[-- Type: text/x-patch, Size: 2225 bytes --]

From b1dc630718c39b2fb630d349f186ac060290c515 Mon Sep 17 00:00:00 2001
From: Lin Sun <sunlin7@hotmail.com>
Date: Thu, 17 Oct 2024 06:50:31 +0000
Subject: [PATCH] * lisp/autorevert.el: Avoid reverting buffer in short time

---
 lisp/autorevert.el | 16 ++++++++++++----
 1 file changed, 12 insertions(+), 4 deletions(-)

diff --git a/lisp/autorevert.el b/lisp/autorevert.el
index 0fdab6ffc9f..ef758584c0d 100644
--- a/lisp/autorevert.el
+++ b/lisp/autorevert.el
@@ -370,6 +370,9 @@ auto-revert-notify-modified-p
   "Non-nil when file has been modified on the file system.
 This has been reported by a file notification event.")
 
+(defvar-local auto-revert--last-time nil
+  "The last time of buffer was reverted.")
+
 (defvar auto-revert-debug nil
   "Use for debug messages.")
 
@@ -749,13 +752,17 @@ auto-revert-notify-handler
               ;; Mark buffer modified.
               (setq auto-revert-notify-modified-p t)
 
-              ;; Revert the buffer now if we're not locked out.
+              ;; Lock out the buffer
               (unless auto-revert--lockout-timer
-                (auto-revert-handler)
                 (setq auto-revert--lockout-timer
                       (run-with-timer
                        auto-revert--lockout-interval nil
-                       #'auto-revert--end-lockout buffer))))))))))
+                       #'auto-revert--end-lockout buffer))
+                ;; Revert it when first entry or it was reverted intervals ago
+                (when (or (null auto-revert--last-time)
+                          (> (float-time (time-since auto-revert--last-time))
+                             auto-revert--lockout-interval))
+                  (auto-revert-handler))))))))))
 
 (defun auto-revert--end-lockout (buffer)
   "End the lockout period after a notification.
@@ -801,7 +808,8 @@ auto-revert-handler
                               #'buffer-stale--default-function)
                           t))))
          eob eoblist)
-    (setq auto-revert-notify-modified-p nil)
+    (setq auto-revert-notify-modified-p nil
+          auto-revert--last-time (current-time))
     (when revert
       (when (and auto-revert-verbose
                  (not (eq revert 'fast)))
-- 
2.34.1

bug#73855: [PATCH] * lisp/autorevert.el: Avoid reverting buffer in short time

[Michael Albinus via Bug reports for GNU Emacs, the Swiss army knife of text editors]

Lin Sun <sunlin7.mail@gmail.com> writes:

> Hi,

Hi,

> High CPU consumption after enabling the "auto-revert" for a buffer.
> Here is a way to reproduce the issue:
> 1. on one terminal run command "strace -f -o /tmp/a.log vi -nw"
> 2. on second terminal, start another emacs and open the file
> /tmp/a.log, enable the "auto-revert" mode on the /tmp/a.log buffer.
>
> Typing on 1st terminal(vi), the strace will continually write the
> /tmp/a.log, and the emacs try to revert the /tmp/a.log buffer again
> and again, then CPU loading turns high.
>
> The function `auto-revert-handler` may be called twice for 2.5 seconds
> intervals on a rapidly changed buffer/file.
>
> The root cause is `auto-revert--end-lockout` will call
> `auto-revert-handler` in which the `auto-revert--lockout-timer` was
> cleared, then the next call `auto-revert-notify-handler` will revert
> the buffer immediately regardless the buffer actually was revert just
> before.
>
> This patch will record when the buffer was reverted and avoid
> reverting it again in the same second.

There is no bug. If auto-revert-use-notify is non-nil, file
notifications are in game, which are *supposed* to revert
immediately. No delay is wanted.

In your case, where mass write happens to a file, I recommend to set
auto-revert-use-notify to nil. Polling is used then instead, with
auto-revert-interval interval between reverts. The default value is 5
(seconds), you might change it to 1.

Furthermore, your use case doesn't look ideal for enabling
auto-revert-mode. Checking fast changing log files is better done with
auto-revert-tail-mode.

Best regards, Michael.

bug#73855: [PATCH] * lisp/autorevert.el: Avoid reverting buffer in short time

[Lin Sun]

On Fri, Oct 18, 2024 at 7:50 AM Michael Albinus <michael.albinus@gmx.de> wrote:
>
> In your case, where mass write happens to a file, I recommend to set
> auto-revert-use-notify to nil. Polling is used then instead, with
> auto-revert-interval interval between reverts. The default value is 5
> (seconds), you might change it to 1.
>
> Furthermore, your use case doesn't look ideal for enabling
> auto-revert-mode. Checking fast changing log files is better done with
> auto-revert-tail-mode.
>
Thanks for the comments, the tail mode worked for me; but actually I
enabled the global-auto-revert-mode, I have to manually switch to tail
mode for some buffers. And yes, the default interval value is 5
seconds.

Let's look at this case: the auto-revert-interval is 5, a writing
happened 1 write / second, total 20 writings (in 20 seconds). The
revert-handler run on: first time (T0), and then locks for 5 seconds;
then T5 lock done, revert the buffer; then T6 reverts the and locks it
again... The revert happened as below:

T0...T5,T6...T11,T12...T17,T18...T23

The T5,T6 are nearby, similar happened on T11,T12, and after each lock
end, there is a revert executed nearby.

This patch try to enhance the lock, then makes the revert happened on:

T0...T5...T10...T15...

That reduced loading on my local.

Best Regards, Lin

bug#73855: [PATCH] * lisp/autorevert.el: Avoid reverting buffer in short time

[Michael Albinus via Bug reports for GNU Emacs, the Swiss army knife of text editors]

Lin Sun <sunlin7.mail@gmail.com> writes:

Hi Lin,

> Let's look at this case: the auto-revert-interval is 5, a writing
> happened 1 write / second, total 20 writings (in 20 seconds). The
> revert-handler run on: first time (T0), and then locks for 5 seconds;
> then T5 lock done, revert the buffer; then T6 reverts the and locks it
> again... The revert happened as below:
>
> T0...T5,T6...T11,T12...T17,T18...T23
>
> The T5,T6 are nearby, similar happened on T11,T12, and after each lock
> end, there is a revert executed nearby.
>
> This patch try to enhance the lock, then makes the revert happened on:
>
> T0...T5...T10...T15...
>
> That reduced loading on my local.

Thanks for explanation, now I understand the scenario.

Your patch makes sense. However, autorevert-tests fail now:

--8<---------------cut here---------------start------------->8---
# make -C test autorevert-tests
make: Entering directory '/home/albinus/src/emacs/test'
make[1]: Entering directory '/home/albinus/src/emacs/test'
  GEN      lisp/autorevert-tests.log
Running 7 tests (2024-10-19 11:02:58+0200, selector `(not (tag :unstable))')
Reverting buffer `emacs-test-zzmdD8-autorevert'
   passed  1/7  auto-revert-test00-auto-revert-mode (3.554035 sec)
(Shell command succeeded with no output)
Reverting buffer `auto-revert-testenE8rY-autorevert'
Reverting buffer `auto-revert-testOJVaub-autorevert'
   passed  2/7  auto-revert-test01-auto-revert-several-files (0.172674 sec)
Reverting buffer `emacs-test-IIR73t-autorevert'
   passed  3/7  auto-revert-test03-auto-revert-tail-mode (2.527101 sec)
Reverting buffer `tmp'
Reverting buffer `tmp'
   passed  4/7  auto-revert-test04-auto-revert-mode-dired (0.457824 sec)
Reverting buffer `emacs-test-i5RWpJ-autorevert'
Test auto-revert-test05-global-notify backtrace:
  signal(ert-test-failed (((should (equal (auto-revert-test--buffer-st
  ert-fail(((should (equal (auto-revert-test--buffer-string buf-2) "2-
  (if (unwind-protect (setq value-171 (apply fn-169 args-170)) (setq f
  (let (form-description-173) (if (unwind-protect (setq value-171 (app
  (let ((value-171 'ert-form-evaluation-aborted-172)) (let (form-descr
  (let* ((fn-169 #'equal) (args-170 (condition-case err (list (auto-re
  (progn (setq buf-1 (find-file-noselect file-1)) (auto-revert-test--i
  (unwind-protect (progn (setq buf-1 (find-file-noselect file-1)) (aut
  (let* ((auto-revert-use-notify t) (auto-revert-avoid-polling t) (was
  (progn (let* ((auto-revert-use-notify t) (auto-revert-avoid-polling
  (unwind-protect (progn (let* ((auto-revert-use-notify t) (auto-rever
  (let* ((coding-system-for-write nil) (temp-file (identity (make-temp
  (progn (let* ((coding-system-for-write nil) (temp-file (identity (ma
  (unwind-protect (progn (let* ((coding-system-for-write nil) (temp-fi
  (let* ((coding-system-for-write nil) (temp-file (identity (make-temp
  (progn (let* ((coding-system-for-write nil) (temp-file (identity (ma
  (unwind-protect (progn (let* ((coding-system-for-write nil) (temp-fi
  (let* ((coding-system-for-write nil) (temp-file (identity (make-temp
  (progn (customize-set-variable 'auto-revert-interval 0.1) (let* ((co
  (unwind-protect (progn (customize-set-variable 'auto-revert-interval
  (let ((auto-revert-interval-orig auto-revert-interval)) (unwind-prot
  #f(lambda () [t] (let ((value-147 (gensym "ert-form-evaluation-abort
  #f(compiled-function () #<bytecode 0x1e80ca290561ae1>)()
  handler-bind-1(#f(compiled-function () #<bytecode 0x1e80ca290561ae1>
  ert--run-test-internal(#s(ert--test-execution-info :test #s(ert-test
  ert-run-test(#s(ert-test :name auto-revert-test05-global-notify :doc
  ert-run-or-rerun-test(#s(ert--stats :selector ... :tests ... :test-m
  ert-run-tests((not (tag :unstable)) #f(compiled-function (event-type
  ert-run-tests-batch((not (tag :unstable)))
  ert-run-tests-batch-and-exit((not (tag :unstable)))
  eval((ert-run-tests-batch-and-exit '(not (tag :unstable))) t)
  command-line-1(("-L" ":." "-l" "ert" "--eval" "(setq treesit-extra-l
  command-line()
  normal-top-level()
Test auto-revert-test05-global-notify condition:
    (ert-test-failed
     ((should (equal (auto-revert-test--buffer-string buf-2) "2-a")) :form
      (equal "" "2-a") :value nil :explanation
      (arrays-of-different-length 0 3 "" "2-a" first-mismatch-at 0)))
   FAILED  5/7  auto-revert-test05-global-notify (1.020224 sec) at lisp/autorevert-tests.el:451
Reverting buffer `emacs-test-cjR4uH-autorevert-2'
   passed  6/7  auto-revert-test06-write-file (0.136182 sec)
Reverting buffer `emacs-test-EnNjg7-autorevert'
Reverting buffer `emacs-test-EnNjg7-autorevert-0'
Reverting buffer `emacs-test-EnNjg7-autorevert-1'
Reverting buffer `emacs-test-EnNjg7-autorevert-2'
Reverting buffer `emacs-test-EnNjg7-autorevert-3'
Reverting buffer `emacs-test-EnNjg7-autorevert-4'
Reverting buffer `emacs-test-EnNjg7-autorevert-5'
Reverting buffer `emacs-test-EnNjg7-autorevert-6'
Reverting buffer `emacs-test-EnNjg7-autorevert-7'
Reverting buffer `emacs-test-EnNjg7-autorevert-8'
Reverting buffer `emacs-test-EnNjg7-autorevert-9'
   passed  7/7  auto-revert-test07-auto-revert-several-buffers (5.077571 sec)

Ran 7 tests, 6 results as expected, 1 unexpected (2024-10-19 11:03:12+0200, 14.040452 sec)

1 unexpected results:
   FAILED  auto-revert-test05-global-notify

make[1]: *** [Makefile:185: lisp/autorevert-tests.log] Error 1
make[1]: Leaving directory '/home/albinus/src/emacs/test'
make: *** [Makefile:251: lisp/autorevert-tests] Error 2
make: Leaving directory '/home/albinus/src/emacs/test'
--8<---------------cut here---------------end--------------->8---

Could you pls check what's up?

> Best Regards, Lin

Best regards, Michael.

bug#73855: [PATCH] * lisp/autorevert.el: Avoid reverting buffer in short time

[Lin Sun]

[-- Attachment #1: Type: text/plain, Size: 683 bytes --]

Hi Michael,

On Sat, Oct 19, 2024 at 9:06 AM Michael Albinus <michael.albinus@gmx.de> wrote:
>
> Thanks for explanation, now I understand the scenario.
>
> Your patch makes sense. However, autorevert-tests fail now:
...
> 1 unexpected results:
>    FAILED  auto-revert-test05-global-notify
>
> make[1]: *** [Makefile:185: lisp/autorevert-tests.log] Error 1
...
> Could you pls check what's up?
>
> Best regards, Michael.

Thank you for found the issue, really appreciate it! The issue was
fixed by setting the variable 'auto-revert--lockout-interval' to the
half value of 'auto-revert-interval' (similar to its definition).

Please help review again, thanks.

[-- Attachment #2: 0001-Enhance-the-auto-revert-to-avoid-revert-a-buffer-in-.patch --]
[-- Type: text/x-patch, Size: 3622 bytes --]

From bc22ff0fc60b2ccb071a18fb55e08bb49f78c25a Mon Sep 17 00:00:00 2001
From: Lin Sun <sunlin7@hotmail.com>
Date: Thu, 17 Oct 2024 06:50:31 +0000
Subject: [PATCH] Enhance the auto-revert to avoid revert a buffer in short
 time

* lisp/autorevert.el: New variable auto-revert--last-time for
  (auto-revert-handler) and (auto-revert-notify-handler).
* test/lisp/autorevert-tests.el: Set the auto-revert--lockout-interval
  correctly in (with-auto-revert-test).
---
 lisp/autorevert.el            | 16 ++++++++++++----
 test/lisp/autorevert-tests.el |  7 +++++--
 2 files changed, 17 insertions(+), 6 deletions(-)

diff --git a/lisp/autorevert.el b/lisp/autorevert.el
index 0fdab6ffc9f..ef758584c0d 100644
--- a/lisp/autorevert.el
+++ b/lisp/autorevert.el
@@ -370,6 +370,9 @@ auto-revert-notify-modified-p
   "Non-nil when file has been modified on the file system.
 This has been reported by a file notification event.")
 
+(defvar-local auto-revert--last-time nil
+  "The last time of buffer was reverted.")
+
 (defvar auto-revert-debug nil
   "Use for debug messages.")
 
@@ -749,13 +752,17 @@ auto-revert-notify-handler
               ;; Mark buffer modified.
               (setq auto-revert-notify-modified-p t)
 
-              ;; Revert the buffer now if we're not locked out.
+              ;; Lock out the buffer
               (unless auto-revert--lockout-timer
-                (auto-revert-handler)
                 (setq auto-revert--lockout-timer
                       (run-with-timer
                        auto-revert--lockout-interval nil
-                       #'auto-revert--end-lockout buffer))))))))))
+                       #'auto-revert--end-lockout buffer))
+                ;; Revert it when first entry or it was reverted intervals ago
+                (when (or (null auto-revert--last-time)
+                          (> (float-time (time-since auto-revert--last-time))
+                             auto-revert--lockout-interval))
+                  (auto-revert-handler))))))))))
 
 (defun auto-revert--end-lockout (buffer)
   "End the lockout period after a notification.
@@ -801,7 +808,8 @@ auto-revert-handler
                               #'buffer-stale--default-function)
                           t))))
          eob eoblist)
-    (setq auto-revert-notify-modified-p nil)
+    (setq auto-revert-notify-modified-p nil
+          auto-revert--last-time (current-time))
     (when revert
       (when (and auto-revert-verbose
                  (not (eq revert 'fast)))
diff --git a/test/lisp/autorevert-tests.el b/test/lisp/autorevert-tests.el
index 4763994c5d4..7e176df6803 100644
--- a/test/lisp/autorevert-tests.el
+++ b/test/lisp/autorevert-tests.el
@@ -132,12 +132,15 @@ auto-revert--deftest-remote
          (error (message "%s" err) (signal (car err) (cdr err)))))))
 
 (defmacro with-auto-revert-test (&rest body)
-  `(let ((auto-revert-interval-orig auto-revert-interval))
+  `(let ((auto-revert-interval-orig auto-revert-interval)
+         (auto-revert--lockout-interval-orig auto-revert--lockout-interval))
      (unwind-protect
          (progn
            (customize-set-variable 'auto-revert-interval 0.1)
+           (setq auto-revert--lockout-interval 0.05)
            ,@body)
-       (customize-set-variable 'auto-revert-interval auto-revert-interval-orig))))
+       (customize-set-variable 'auto-revert-interval auto-revert-interval-orig)
+       (setq auto-revert--lockout-interval auto-revert--lockout-interval-orig))))
 
 (defun auto-revert-tests--write-file (text file time-delta &optional append)
   (write-region text nil file append 'no-message)
-- 
2.34.1

bug#73855: [PATCH] * lisp/autorevert.el: Avoid reverting buffer in short time

[Michael Albinus via Bug reports for GNU Emacs, the Swiss army knife of text editors]

Version: 31.1

Lin Sun <sunlin7.mail@gmail.com> writes:

> Hi Michael,

Hi Lin,

> Thank you for found the issue, really appreciate it! The issue was
> fixed by setting the variable 'auto-revert--lockout-interval' to the
> half value of 'auto-revert-interval' (similar to its definition).
>
> Please help review again, thanks.

This looks good now. I've pushed it to master, closing the bug.

Best regards, Michael.

bug#73855: [PATCH] * lisp/autorevert.el: Avoid reverting buffer in short time

[Lin Sun]

On Sun, Oct 20, 2024 at 9:15 AM Michael Albinus <michael.albinus@gmx.de> wrote:
>
> Version: 31.1
>
> Lin Sun <sunlin7.mail@gmail.com> writes:
>
> > Hi Michael,
>
> Hi Lin,
>
> > Thank you for found the issue, really appreciate it! The issue was
> > fixed by setting the variable 'auto-revert--lockout-interval' to the
> > half value of 'auto-revert-interval' (similar to its definition).
> >
> > Please help review again, thanks.
>
> This looks good now. I've pushed it to master, closing the bug.
>
> Best regards, Michael.

Hi Michael,

Thank you so much!

Best regards, Lin