bug#55628: debug-timer-check fails on macOS 11.6.6

bug#55628: debug-timer-check fails on macOS 11.6.6

[Mattias Engdegård]

Built with enable-checking, (debug-timer-check) returns nil.
It turns out that debug_timer_callback is never actually called, but I haven't dug further than that.

This is on macOS 11.6.6 and HAVE_TIMERFD is not defined. Does this code path work on other systems?

bug#55628: debug-timer-check fails on macOS 11.6.6

[Lars Ingebrigtsen]

Mattias Engdegård <mattiase@acm.org> writes:

> Built with enable-checking, (debug-timer-check) returns nil.
> It turns out that debug_timer_callback is never actually called, but I
> haven't dug further than that.
>
> This is on macOS 11.6.6 and HAVE_TIMERFD is not defined. Does this
> code path work on other systems?

I tried this on Debian/bookworm (with nativecomp, but that probably
doesn't make a difference), and I got nil there, too.

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no

bug#55628: debug-timer-check fails on macOS 11.6.6

[Mattias Engdegård]

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

25 maj 2022 kl. 14.20 skrev Lars Ingebrigtsen <larsi@gnus.org>:
> 
> Mattias Engdegård <mattiase@acm.org> writes:
> 
>> Built with enable-checking, (debug-timer-check) returns nil.
>> It turns out that debug_timer_callback is never actually called, but I
>> haven't dug further than that.
>> 
>> This is on macOS 11.6.6 and HAVE_TIMERFD is not defined. Does this
>> code path work on other systems?
> 
> I tried this on Debian/bookworm (with nativecomp, but that probably
> doesn't make a difference), and I got nil there, too.

Thanks for checking. Apparently pending_signals is never set; handle_alarm_signal is never called.
More digging shows that set_alarm always sets the interval timer to at least 1 ms in the future even if the timer has expired.

The attached patch makes set_alarm signal SIGALRM immediately if the timer is due. We could call the signal handler directly but this way it should work correctly if the signal is masked at the moment. What do you think?


[-- Attachment #2: set_alarm.diff --]
[-- Type: application/octet-stream, Size: 1453 bytes --]

diff --git a/src/atimer.c b/src/atimer.c
index 1c6c881fc0..c26904e1f0 100644
--- a/src/atimer.c
+++ b/src/atimer.c
@@ -297,11 +297,6 @@ set_alarm (void)
 {
   if (atimers)
     {
-#ifdef HAVE_SETITIMER
-      struct itimerval it;
-#endif
-      struct timespec now, interval;
-
 #ifdef HAVE_ITIMERSPEC
       if (0 <= timerfd || alarm_timer_ok)
 	{
@@ -337,20 +332,24 @@ set_alarm (void)
 	}
 #endif
 
-      /* Determine interval till the next timer is ripe.
-	 Don't set the interval to 0; this disables the timer.  */
-      now = current_timespec ();
-      interval = (timespec_cmp (atimers->expiration, now) <= 0
-		  ? make_timespec (0, 1000 * 1000)
-		  : timespec_sub (atimers->expiration, now));
+      /* Determine interval till the next timer is ripe.  */
+      struct timespec now = current_timespec ();
+      if (timespec_cmp (atimers->expiration, now) <= 0)
+	{
+	  /* Timer is (over)due -- just trigger the signal right way.  */
+	  raise (SIGALRM);
+	}
+      else
+	{
+	  struct timespec interval = timespec_sub (atimers->expiration, now);
 
 #ifdef HAVE_SETITIMER
-
-      memset (&it, 0, sizeof it);
-      it.it_value = make_timeval (interval);
-      setitimer (ITIMER_REAL, &it, 0);
-#endif /* not HAVE_SETITIMER */
-      alarm (max (interval.tv_sec, 1));
+	  struct itimerval it = {.it_value = make_timeval (interval)};
+	  setitimer (ITIMER_REAL, &it, 0);
+#else
+	  alarm (max (interval.tv_sec, 1));
+#endif
+	}
     }
 }
 

bug#55628: debug-timer-check fails on macOS 11.6.6

[Eli Zaretskii]

> Cc: 55628@debbugs.gnu.org
> From: Mattias Engdegård <mattiase@acm.org>
> Date: Wed, 25 May 2022 15:05:32 +0200
> 
> Thanks for checking. Apparently pending_signals is never set; handle_alarm_signal is never called.
> More digging shows that set_alarm always sets the interval timer to at least 1 ms in the future even if the timer has expired.
> 
> The attached patch makes set_alarm signal SIGALRM immediately if the timer is due. We could call the signal handler directly but this way it should work correctly if the signal is masked at the moment. What do you think?

I'd prefer not to change the logic of set_alarm just to have a
debugging aid working.  Can we come up with a more compatible change,
which doesn't affect calls to set_alarm except during this test?

Thanks.

bug#55628: debug-timer-check fails on macOS 11.6.6

[Mattias Engdegård]

25 maj 2022 kl. 15.05 skrev Mattias Engdegård <mattiase@acm.org>:

> More digging shows that set_alarm always sets the interval timer to at least 1 ms in the future even if the timer has expired.

In fact it was even worse than that: because of a second bug, the timer was then immediately reset to at least 1 s in the future. The proposed patch fixes both flaws.

Good to have a test for it -- maybe it should always be enabled, not just with enable-checking? People don't always reconfigure, rebuild and re-run the tests with enable-checking, nor do any of the build bots.

bug#55628: debug-timer-check fails on macOS 11.6.6

[Eli Zaretskii]

> Resent-From: Mattias Engdegård <mattiase@acm.org>
> Original-Sender: "Debbugs-submit" <debbugs-submit-bounces@debbugs.gnu.org>
> Resent-CC: bug-gnu-emacs@gnu.org
> Resent-Sender: help-debbugs@gnu.org
> Cc: 55628@debbugs.gnu.org
> From: Mattias Engdegård <mattiase@acm.org>
> Date: Wed, 25 May 2022 17:34:57 +0200
> 
> 25 maj 2022 kl. 15.05 skrev Mattias Engdegård <mattiase@acm.org>:
> 
> > More digging shows that set_alarm always sets the interval timer to at least 1 ms in the future even if the timer has expired.
> 
> In fact it was even worse than that: because of a second bug, the timer was then immediately reset to at least 1 s in the future. The proposed patch fixes both flaws.

Btw, this test will never work on a platform that only has setitimer,
because only one ITIMER_REAL timer is guaranteed to exist, and the
function attempts to arm 10 timers at the same time.

> Good to have a test for it -- maybe it should always be enabled, not just with enable-checking? People don't always reconfigure, rebuild and re-run the tests with enable-checking, nor do any of the build bots.

We don't usually have testing code in a production build, so why make
an exception here?  Especially since atimers are an obscure feature
used internally by Emacs.

bug#55628: debug-timer-check fails on macOS 11.6.6

[Mattias Engdegård]

25 maj 2022 kl. 19.11 skrev Eli Zaretskii <eliz@gnu.org>:

> Btw, this test will never work on a platform that only has setitimer,
> because only one ITIMER_REAL timer is guaranteed to exist, and the
> function attempts to arm 10 timers at the same time.

That's not how the code works. `setitimer` will only be called for the first timer to expire.
(The test works correctly on this computer, that only has setitimer, after applying the patch.)

Another demonstration of this bug:

(funcall-with-delayed-message
 0.1 "haha" (lambda () (sit-for 3)))

will, on this machine, display "haha" after 1 s if unpatched, but after 0.1 s if patched.

(This is with -nw because the NS backend seems to be slow handling async events on its own, but that's a different bug.)

> We don't usually have testing code in a production build, so why make
> an exception here?  Especially since atimers are an obscure feature
> used internally by Emacs.

There's nothing bad or even unusual about including interfaces for internal testing in production builds, as long as it doesn't unduly reduce performance or cause significant bloat. It's always a trade-off, of course.

bug#55628: debug-timer-check fails on macOS 11.6.6

[Eli Zaretskii]

> From: Mattias Engdegård <mattiase@acm.org>
> Date: Thu, 26 May 2022 11:57:58 +0200
> Cc: larsi@gnus.org, 55628@debbugs.gnu.org
> 
> 25 maj 2022 kl. 19.11 skrev Eli Zaretskii <eliz@gnu.org>:
> 
> > Btw, this test will never work on a platform that only has setitimer,
> > because only one ITIMER_REAL timer is guaranteed to exist, and the
> > function attempts to arm 10 timers at the same time.
> 
> That's not how the code works. `setitimer` will only be called for the first timer to expire.

Maybe I've misread the code, then.  Apologies.

> > We don't usually have testing code in a production build, so why make
> > an exception here?  Especially since atimers are an obscure feature
> > used internally by Emacs.
> 
> There's nothing bad or even unusual about including interfaces for internal testing in production builds, as long as it doesn't unduly reduce performance or cause significant bloat. It's always a trade-off, of course.

Not in principle, but we in this project don't do that.  E.g., there
are several debug-related functions and commands in xdisp.c that are
only compiled in under ENABLE_CHECKING.

So if we are going to make an exception for this case, we should have
some good reason.

bug#55628: debug-timer-check fails on macOS 11.6.6

[Mattias Engdegård]

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

26 maj 2022 kl. 13.37 skrev Eli Zaretskii <eliz@gnu.org>:

> Not in principle, but we in this project don't do that.  E.g., there
> are several debug-related functions and commands in xdisp.c that are
> only compiled in under ENABLE_CHECKING.

I don't think that not having done it in the past is justification enough for not doing it now, but I agree that it would be preferable to have it covered by a test that doesn't need a special interface.

It looks like funcall-with-delayed-message could be used for this purpose. I came up with the attached test, which also has the benefit of extending test coverage to that function which previously had none.


[-- Attachment #2: funcall-with-delayed-message-test.diff --]
[-- Type: application/octet-stream, Size: 1510 bytes --]

diff --git a/test/src/eval-tests.el b/test/src/eval-tests.el
index e4230c10ef..1b2ad99360 100644
--- a/test/src/eval-tests.el
+++ b/test/src/eval-tests.el
@@ -240,4 +240,31 @@ eval-tests/backtrace-in-batch-mode/demoted-errors
       (should (equal (string-trim (buffer-string))
                      "Error: (error \"Boo\")")))))
 
+(ert-deftest eval-tests/funcall-with-delayed-message ()
+  ;; Check that `funcall-with-delayed-message' displays its message before
+  ;; its function terminates iff the timeout is short enough.
+
+  ;; This also serves as regression test for bug#55628 where a short
+  ;; timeout was rounded up to the next whole second.
+  (dolist (params '((0.8 0.4)
+                    (0.1 0.8)))
+    (let ((timeout (nth 0 params))
+          (work-time (nth 1 params)))
+      (ert-info ((prin1-to-string params) :prefix "params: ")
+        (with-current-buffer "*Messages*"
+          (let ((inhibit-read-only t))
+            (erase-buffer))
+          (let ((stop (+ (float-time) work-time)))
+            (funcall-with-delayed-message
+             timeout "timed out"
+             (lambda ()
+               (while (< (float-time) stop))
+               (message "finished"))))
+          (let ((expected-messages
+                 (if (< timeout work-time)
+                     "timed out\nfinished"
+                   "finished")))
+            (should (equal (string-trim (buffer-string))
+                           expected-messages))))))))
+
 ;;; eval-tests.el ends here

bug#55628: debug-timer-check fails on macOS 11.6.6

[Mattias Engdegård]

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

Attached is the final patch (just the two previously combined with a commit message).

Would someone please double-check that it works on a platform other than macOS before I push it?


[-- Attachment #2: 0001-Fix-atimer-setting-and-overdue-expiration-bug-55628.patch --]
[-- Type: application/octet-stream, Size: 4192 bytes --]

From 671716186fc6d2506d06e85485faad405a365e6a Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Mattias=20Engdeg=C3=A5rd?= <mattiase@acm.org>
Date: Mon, 30 May 2022 12:25:19 +0200
Subject: [PATCH] Fix atimer setting and overdue expiration (bug#55628)

* src/atimer.c (set_alarm): If the atimer has already expired, signal
it right away instead of postponing it further.  Previously this could
occur repeatedly, blocking atimers indefinitely.
Also only use `alarm` as fallback if `setitimer` is unavailable, not
both at the same time (which makes no sense, and they both typically
use the same mechanism behind the curtains).

* test/src/eval-tests.el (eval-tests/funcall-with-delayed-message):
New test, verifying proper functioning of funcall-with-delayed-message
which also serves as test for this bug (which also caused
debug-timer-check to fail, but that test is only run when Emacs is
built with enable-checking).
---
 src/atimer.c           | 33 ++++++++++++++++-----------------
 test/src/eval-tests.el | 27 +++++++++++++++++++++++++++
 2 files changed, 43 insertions(+), 17 deletions(-)

diff --git a/src/atimer.c b/src/atimer.c
index 1c6c881fc0..c26904e1f0 100644
--- a/src/atimer.c
+++ b/src/atimer.c
@@ -297,11 +297,6 @@ set_alarm (void)
 {
   if (atimers)
     {
-#ifdef HAVE_SETITIMER
-      struct itimerval it;
-#endif
-      struct timespec now, interval;
-
 #ifdef HAVE_ITIMERSPEC
       if (0 <= timerfd || alarm_timer_ok)
 	{
@@ -337,20 +332,24 @@ set_alarm (void)
 	}
 #endif
 
-      /* Determine interval till the next timer is ripe.
-	 Don't set the interval to 0; this disables the timer.  */
-      now = current_timespec ();
-      interval = (timespec_cmp (atimers->expiration, now) <= 0
-		  ? make_timespec (0, 1000 * 1000)
-		  : timespec_sub (atimers->expiration, now));
+      /* Determine interval till the next timer is ripe.  */
+      struct timespec now = current_timespec ();
+      if (timespec_cmp (atimers->expiration, now) <= 0)
+	{
+	  /* Timer is (over)due -- just trigger the signal right way.  */
+	  raise (SIGALRM);
+	}
+      else
+	{
+	  struct timespec interval = timespec_sub (atimers->expiration, now);
 
 #ifdef HAVE_SETITIMER
-
-      memset (&it, 0, sizeof it);
-      it.it_value = make_timeval (interval);
-      setitimer (ITIMER_REAL, &it, 0);
-#endif /* not HAVE_SETITIMER */
-      alarm (max (interval.tv_sec, 1));
+	  struct itimerval it = {.it_value = make_timeval (interval)};
+	  setitimer (ITIMER_REAL, &it, 0);
+#else
+	  alarm (max (interval.tv_sec, 1));
+#endif
+	}
     }
 }
 
diff --git a/test/src/eval-tests.el b/test/src/eval-tests.el
index e4230c10ef..1b2ad99360 100644
--- a/test/src/eval-tests.el
+++ b/test/src/eval-tests.el
@@ -240,4 +240,31 @@ eval-tests/backtrace-in-batch-mode/demoted-errors
       (should (equal (string-trim (buffer-string))
                      "Error: (error \"Boo\")")))))
 
+(ert-deftest eval-tests/funcall-with-delayed-message ()
+  ;; Check that `funcall-with-delayed-message' displays its message before
+  ;; its function terminates iff the timeout is short enough.
+
+  ;; This also serves as regression test for bug#55628 where a short
+  ;; timeout was rounded up to the next whole second.
+  (dolist (params '((0.8 0.4)
+                    (0.1 0.8)))
+    (let ((timeout (nth 0 params))
+          (work-time (nth 1 params)))
+      (ert-info ((prin1-to-string params) :prefix "params: ")
+        (with-current-buffer "*Messages*"
+          (let ((inhibit-read-only t))
+            (erase-buffer))
+          (let ((stop (+ (float-time) work-time)))
+            (funcall-with-delayed-message
+             timeout "timed out"
+             (lambda ()
+               (while (< (float-time) stop))
+               (message "finished"))))
+          (let ((expected-messages
+                 (if (< timeout work-time)
+                     "timed out\nfinished"
+                   "finished")))
+            (should (equal (string-trim (buffer-string))
+                           expected-messages))))))))
+
 ;;; eval-tests.el ends here
-- 
2.32.0 (Apple Git-132)

bug#55628: debug-timer-check fails on macOS 11.6.6

[Lars Ingebrigtsen]

Mattias Engdegård <mattiase@acm.org> writes:

> Attached is the final patch (just the two previously combined with a
> commit message).
>
> Would someone please double-check that it works on a platform other
> than macOS before I push it?

Works for me on Debian/bullseye (that is, no compilation warnings and
the tests pass).

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no

bug#55628: debug-timer-check fails on macOS 11.6.6

[Mattias Engdegård]

30 maj 2022 kl. 15.42 skrev Lars Ingebrigtsen <larsi@gnus.org>:

> Works for me on Debian/bullseye (that is, no compilation warnings and
> the tests pass).

Thank you, now pushed to master.