bug#39944: 27.0.90; JIT Stealth timer errors

bug#39944: 27.0.90; JIT Stealth timer errors

[Eli Zaretskii]

I see these errors in the 27.0.90 pretest from time to time:

  Error running timer ‘jit-lock-stealth-fontify’: (error "Invalid time format")

This didn't happen in previous versions of Emacs, so I think this is
some regression, most probably due to changes in timer.el or related
time functions.

Does anyone else see this?  (You have to enable jit-lock-stealth to
see this.)


In GNU Emacs 27.0.90 (build 1, i686-pc-mingw32)
 of 2020-03-01 built on HOME-C4E4A596F7
Windowing system distributor 'Microsoft Corp.', version 5.1.2600
System Description: Microsoft Windows XP Service Pack 3 (v5.1.0.2600)

Recent messages:
Getting mail from d:/usr/eli/data/mail.new...
Counting new messages...done (1)
Saving file d:/usr/eli/rmail/INBOX...
Wrote d:/usr/eli/rmail/INBOX
Computing summary lines...done
1 new message read
No following nondeleted message
Saving file d:/usr/eli/rmail/INBOX...
Wrote d:/usr/eli/rmail/INBOX
Error running timer ‘jit-lock-stealth-fontify’: (error "Invalid time format") [2 times]

Configured using:
 'configure -C --prefix=/d/usr --with-wide-int --with-modules
 'CFLAGS=-Og -gdwarf-4 -g3''

Configured features:
XPM JPEG TIFF GIF PNG RSVG SOUND NOTIFY W32NOTIFY ACL GNUTLS LIBXML2
HARFBUZZ ZLIB TOOLKIT_SCROLL_BARS MODULES THREADS JSON PDUMPER LCMS2
GMP

Important settings:
  value of $LANG: ENU
  locale-coding-system: cp1255

Major mode: RMAIL

Minor modes in effect:
  shell-dirtrack-mode: t
  desktop-save-mode: t
  save-place-mode: t
  show-paren-mode: t
  display-battery-mode: t
  display-time-mode: t
  tooltip-mode: t
  global-eldoc-mode: t
  electric-indent-mode: t
  mouse-wheel-mode: t
  tool-bar-mode: t
  menu-bar-mode: t
  file-name-shadow-mode: t
  global-font-lock-mode: t
  font-lock-mode: t
  blink-cursor-mode: t
  auto-composition-mode: t
  auto-encryption-mode: t
  auto-compression-mode: t
  temp-buffer-resize-mode: t
  buffer-read-only: t
  line-number-mode: t

Load-path shadows:
d:/usr/share/emacs/site-lisp/soap-inspect hides d:/usr/share/emacs/27.0.90/lisp/net/soap-inspect
d:/usr/share/emacs/site-lisp/soap-client hides d:/usr/share/emacs/27.0.90/lisp/net/soap-client

Features:
(shadow emacsbug pcase shell pcomplete comint ansi-color rfc2104
gnutls network-stream nsm mail-extr smtpmail mailalias sendmail
eieio-opt speedbar sb-image ezimage dframe find-func mule-diag
help-fns radix-tree misearch multi-isearch time-stamp shr-color color
shr url-cookie url-domsuf url-util url-parse auth-source json map
url-vars svg xml dom browse-url cl-extra help-mode make-mode conf-mode
bat-mode noutline outline cc-awk jka-compr vc-cvs vc-dispatcher vc-bzr
texinfo mule-util info view enriched flyspell add-log vc-git diff-mode
easy-mmode bug-reference rmailsum qp rmailmm message rmc puny
format-spec rfc822 mml mml-sec password-cache epa epg epg-config
gnus-util text-property-search time-date subr-x seq mm-decode
mm-bodies mm-encode mailabbrev gmm-utils mailheader mail-parse rfc2231
rmail rmail-loaddefs rfc2047 rfc2045 ietf-drums mm-util mail-prsvr
mail-utils desktop frameset server find-lisp dired dired-loaddefs
filecache mairix cus-edit cus-start cus-load wid-edit saveplace
midnight ispell derived generic-x cc-mode cc-fonts easymenu cc-guess
cc-menus cc-cmds cc-styles cc-align cc-engine cc-vars cc-defs paren
xref cl-seq project ring eieio byte-opt bytecomp byte-compile cconv
eieio-core cl-macs gv eieio-loaddefs cl-loaddefs cl-lib battery time
tooltip eldoc electric uniquify ediff-hook vc-hooks lisp-float-type
mwheel dos-w32 ls-lisp disp-table term/w32-win w32-win w32-vars
term/common-win tool-bar dnd fontset image regexp-opt fringe
tabulated-list replace newcomment text-mode elisp-mode lisp-mode
prog-mode register page tab-bar menu-bar rfn-eshadow isearch timer
select scroll-bar mouse jit-lock font-lock syntax facemenu font-core
term/tty-colors frame minibuffer 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 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 w32notify w32 lcms2
multi-tty make-network-process emacs)

Memory information:
((conses 16 526189 45228)
 (symbols 48 20376 1)
 (strings 16 118191 2769)
 (string-bytes 1 3365518)
 (vectors 16 32257)
 (vector-slots 8 464721 70974)
 (floats 8 282 384)
 (intervals 40 56525 1222)
 (buffers 888 238))

bug#39944: 27.0.90; JIT Stealth timer errors

[Eli Zaretskii]

> Date: Fri, 06 Mar 2020 12:01:46 +0200
> From: Eli Zaretskii <eliz@gnu.org>
> 
> 
> I see these errors in the 27.0.90 pretest from time to time:
> 
>   Error running timer ‘jit-lock-stealth-fontify’: (error "Invalid time format")

Additional information which is probably related: the *Message* buffer
shows this from time to time:

  run-at-time: Invalid time format
  ([nil 24162 5043 0 5 display-time-event-handler nil nil 0] [nil 24162 5046 46875 nil undo-auto--boundary-timer nil nil 0] [nil 24162 5098 187500 60 battery-update-handler nil nil 0] [nil 24162 54768 140625 86400 run-hooks (midnight-hook) nil 0])

bug#39944: 27.0.90; JIT Stealth timer errors

[Eli Zaretskii]

> Date: Fri, 06 Mar 2020 12:06:03 +0200
> From: Eli Zaretskii <eliz@gnu.org>
> 
> > Date: Fri, 06 Mar 2020 12:01:46 +0200
> > From: Eli Zaretskii <eliz@gnu.org>
> > 
> > 
> > I see these errors in the 27.0.90 pretest from time to time:
> > 
> >   Error running timer ‘jit-lock-stealth-fontify’: (error "Invalid time format")
> 
> Additional information which is probably related: the *Message* buffer
> shows this from time to time:
> 
>   run-at-time: Invalid time format
>   ([nil 24162 5043 0 5 display-time-event-handler nil nil 0] [nil 24162 5046 46875 nil undo-auto--boundary-timer nil nil 0] [nil 24162 5098 187500 60 battery-update-handler nil nil 0] [nil 24162 54768 140625 86400 run-hooks (midnight-hook) nil 0])

This message comes from this fragment of run-at-time:

  (or (consp time)
      (error "Invalid time format"))

I guess this means the problem is general with timers, not specific to
JIT Stealth.

bug#39944: 27.0.90; JIT Stealth timer errors

[Eli Zaretskii]

> Date: Fri, 06 Mar 2020 12:16:07 +0200
> From: Eli Zaretskii <eliz@gnu.org>
> 
> > Additional information which is probably related: the *Message* buffer
> > shows this from time to time:
> > 
> >   run-at-time: Invalid time format
> >   ([nil 24162 5043 0 5 display-time-event-handler nil nil 0] [nil 24162 5046 46875 nil undo-auto--boundary-timer nil nil 0] [nil 24162 5098 187500 60 battery-update-handler nil nil 0] [nil 24162 54768 140625 86400 run-hooks (midnight-hook) nil 0])
> 
> This message comes from this fragment of run-at-time:
> 
>   (or (consp time)
>       (error "Invalid time format"))
> 
> I guess this means the problem is general with timers, not specific to
> JIT Stealth.

The problem is in run-at-time, here:

  ;; Handle numbers as relative times in seconds.
  (if (numberp time)
      (setq time (timer-relative-time nil time)))

This is assumed to always produce time in list format, but at least on
my system (32-bit build --with-wide-int) it sometimes produces an
integer.  I instrumented run-at-time and got a backtrace that clearly
shows that run-at-time was called with the first arg zero, and the
value returned from time-relative-time was a (large) integer.  Looking
at time_arith, I see that this could happen when HZ is computed to be
the number 1.  I tried to figure out why this happens, but quickly got
lost (the comments in that part of the code can really use some
enhancement; they currently seem to target only experts in both time
handling and GMP: many macros whose names don't explain what they do,
and plethora of calls to libgmp functions that have no comments
whatsoever).

Assuming that an integer value is legitimate in that place, here's the
change I propose; since making that change locally, I didn't have even
a single error of this kind:

diff --git a/lisp/emacs-lisp/timer.el b/lisp/emacs-lisp/timer.el
index 74a9495..e61c1a6 100644
--- a/lisp/emacs-lisp/timer.el
+++ b/lisp/emacs-lisp/timer.el
@@ -353,8 +353,10 @@ run-at-time
       (setq time (timer-next-integral-multiple-of-time (current-time) repeat)))
 
   ;; Handle numbers as relative times in seconds.
-  (if (numberp time)
-      (setq time (timer-relative-time nil time)))
+  (when (numberp time)
+    (setq time (timer-relative-time nil time))
+    (or (consp time)
+        (setq time (time-convert time 'list))))
 
   ;; Handle relative times like "2 hours 35 minutes"
   (if (stringp time)

bug#39944: 27.0.90; JIT Stealth timer errors

[Paul Eggert]

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

On 3/6/20 8:11 AM, Eli Zaretskii wrote:

> (the comments in that part of the code can really use some
> enhancement; they currently seem to target only experts in both time
> handling and GMP: many macros whose names don't explain what they do,
> and plethora of calls to libgmp functions that have no comments
> whatsoever).

Although comments in that area no doubt could use improvement, I'd rather not 
see comments like this:

       /* Add TM_YEAR_BASE to mpz[0].  */
       mpz_add_ui (mpz[0], mpz[0], TM_YEAR_BASE);

as they would be the rough equivalent of:

       /* Add 1 to I.  */
       i++;

> +  (when (numberp time)
> +    (setq time (timer-relative-time nil time))
> +    (or (consp time)
> +        (setq time (time-convert time 'list))))

This would catch some problems but not all, as the real bug here is in the code 
(or (consp time) (error "Invalid time format")) which occurs a few lines later. 
As near as I can tell this later code is both wrong and unnecessary. It's wrong 
because it's no longer true that only conses are time values. It's unnecessary 
because the immediately following (timer-set-function timer function args) call 
checks the validity of TIME. On the off chance that a validity check is still 
helpful (because we don't want to create garbage?) I installed the attached 
patch. But it might be better in master to remove the "Invalid time format" 
check entirely.

[-- Attachment #2: 0001-Fix-bug-with-JIT-stealth-timers.patch --]
[-- Type: text/x-patch, Size: 1011 bytes --]

From 363d927086dbdc4e5073393889b76eb0470785f4 Mon Sep 17 00:00:00 2001
From: Paul Eggert <eggert@cs.ucla.edu>
Date: Sat, 7 Mar 2020 09:47:03 -0800
Subject: [PATCH] Fix bug with JIT stealth timers
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

* lisp/emacs-lisp/timer.el (run-at-time): Don’t assume that Lisp
time values must be conses (Bug#39944).
---
 lisp/emacs-lisp/timer.el | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/lisp/emacs-lisp/timer.el b/lisp/emacs-lisp/timer.el
index 74a94957e7..9eb8feed0f 100644
--- a/lisp/emacs-lisp/timer.el
+++ b/lisp/emacs-lisp/timer.el
@@ -378,7 +378,7 @@ This function returns a timer object which you can use in
                                  (decoded-time-year now)
                                  (decoded-time-zone now)))))))
 
-  (or (consp time)
+  (or (time-equal-p time time)
       (error "Invalid time format"))
 
   (let ((timer (timer-create)))
-- 
2.17.1

bug#39944: 27.0.90; JIT Stealth timer errors

[Eli Zaretskii]

> Cc: 39944@debbugs.gnu.org
> From: Paul Eggert <eggert@cs.ucla.edu>
> Date: Sat, 7 Mar 2020 10:02:28 -0800
> 
> > (the comments in that part of the code can really use some
> > enhancement; they currently seem to target only experts in both time
> > handling and GMP: many macros whose names don't explain what they do,
> > and plethora of calls to libgmp functions that have no comments
> > whatsoever).
> 
> Although comments in that area no doubt could use improvement, I'd rather not 
> see comments like this:
> 
>        /* Add TM_YEAR_BASE to mpz[0].  */
>        mpz_add_ui (mpz[0], mpz[0], TM_YEAR_BASE);

There are quite a few of similar comments there, and they actually
help, because they save us from consulting the GMP manual on every
step.

But I really meant that stuff like this lacks a comment:

      hz = make_integer_mpz ();
      mpz_swap (mpz[0], *iticks);
      ticks = make_integer_mpz ();

And also functions like timespec_ticks, lisp_time_hz_ticks, and
lisp_time_seconds, which don't have a single comment describing how
they do their thing.  Following that code with the purpose of tracking
some specific result is not for the faint at heart.  I think adding a
comment here and there might make that easier.

> > +  (when (numberp time)
> > +    (setq time (timer-relative-time nil time))
> > +    (or (consp time)
> > +        (setq time (time-convert time 'list))))
> 
> This would catch some problems but not all, as the real bug here is in the code 
> (or (consp time) (error "Invalid time format")) which occurs a few lines later. 
> As near as I can tell this later code is both wrong and unnecessary. It's wrong 
> because it's no longer true that only conses are time values. It's unnecessary 
> because the immediately following (timer-set-function timer function args) call 
> checks the validity of TIME. On the off chance that a validity check is still 
> helpful (because we don't want to create garbage?) I installed the attached 
> patch.

Thanks.

> But it might be better in master to remove the "Invalid time format"
> check entirely.

I'm fine with removing that test, if we are sure that invoking
run-at-time with something utterly un-timely, like a symbol or a a
string that cannot be a valid time description, will trigger an error
(presumably from timer-set-time).

bug#39944: 27.0.90; JIT Stealth timer errors

[Paul Eggert]

>> Although comments in that area no doubt could use improvement, I'd rather not 
>> see comments like this:
>> 
>>        /* Add TM_YEAR_BASE to mpz[0].  */
>>        mpz_add_ui (mpz[0], mpz[0], TM_YEAR_BASE);
> 
> There are quite a few of similar comments there,

I don't see any similar comments for simple calls from Emacs to mpz_add_ui. And 
I doubt whether there should be, any more than image.c should have comments like 
this:

   /* Use components from GC to draw a line on DPY's PIXMAP from (X, Y)
      to (X+WIDTH-1, Y+HEIGHT-1).  */
   XDrawLine (dpy, pixmap, gc, x, y, x + width - 1, y + height - 1);

Emacs does not do comments like that, because they would clutter the code if you 
already know what XDrawLine does; and if you don't know, it's easy enough to 
look it up - which you should do anyway, and you'll need to do it anyway if you 
want to understand commentary like "components from GC" and "DPY's PIXMAP".

Similarly for nearly every library function Emacs calls. GMP should be no 
different from other libraries in this respect.

> But I really meant that stuff like this lacks a comment:
> 
>       hz = make_integer_mpz ();
>       mpz_swap (mpz[0], *iticks);
>       ticks = make_integer_mpz ();
> 
> And also functions like timespec_ticks, lisp_time_hz_ticks, and
> lisp_time_seconds, which don't have a single comment describing how
> they do their thing.

I added a few comments here and there. But I didn't go down to the level of 
commenting every call.

>> But it might be better in master to remove the "Invalid time format"
>> check entirely.
> 
> I'm fine with removing that test, if we are sure that invoking
> run-at-time with something utterly un-timely, like a symbol or a a
> string that cannot be a valid time description, will trigger an error
> (presumably from timer-set-time).

Yes, that's what happens. I removed the test in master.

bug#39944: 27.0.90; JIT Stealth timer errors

[Eli Zaretskii]

> From: Paul Eggert <eggert@cs.ucla.edu>
> Cc: 39944@debbugs.gnu.org
> Date: Sun, 8 Mar 2020 00:41:05 -0800
> 
> >> Although comments in that area no doubt could use improvement, I'd rather not 
> >> see comments like this:
> >> 
> >>        /* Add TM_YEAR_BASE to mpz[0].  */
> >>        mpz_add_ui (mpz[0], mpz[0], TM_YEAR_BASE);
> > 
> > There are quite a few of similar comments there,
> 
> I don't see any similar comments for simple calls from Emacs to mpz_add_ui.

You interpret what I said too literally.  I meant these examples:

      /* The plan is to compute (na * (db/g) + nb * (da/g)) / lcm (da, db)
	 where g = gcd (da, db).  Start by computing g.  */
      mpz_t *g = &mpz[3];
      mpz_gcd (*g, *da, *db);

      /* fa = da/g, fb = db/g.  */
      mpz_t *fa = &mpz[4], *fb = &mpz[3];
      mpz_divexact (*fa, *da, *g);
      mpz_divexact (*fb, *db, *g);

      /* ihz = fa * db.  This is equal to lcm (da, db).  */
      mpz_t *ihz = &mpz[0];
      mpz_mul (*ihz, *fa, *db);

      /* iticks = (fb * na) OP (fa * nb), where OP is + or -.  */
      mpz_t const *na = bignum_integer (iticks, ta.ticks);
      mpz_mul (*iticks, *fb, *na);
      mpz_t const *nb = bignum_integer (&mpz[3], tb.ticks);
      (subtract ? mpz_submul : mpz_addmul) (*iticks, *fa, *nb);

Quite helpful, I'd say.

> Similarly for nearly every library function Emacs calls. GMP should be no 
> different from other libraries in this respect.

I think it's different, because using it essentially converts infix
expressions to a long series of function calls, and thus significantly
slows down code reading and makes its comprehension harder.  Most
other libraries don't force us to issue so many library calls with
such high density, in order to do relatively simple calculations.

> I added a few comments here and there. But I didn't go down to the level of 
> commenting every call.

Thanks.

bug#39944: 27.0.90; JIT Stealth timer errors

[Lars Ingebrigtsen]

Eli Zaretskii <eliz@gnu.org> writes:

>> I added a few comments here and there. But I didn't go down to the level of 
>> commenting every call.
>
> Thanks.

It looks like all the actionable items here were taken care of, so I'm
closing this bug report.

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