GNU bug report logs - #39944
27.0.90; JIT Stealth timer errors

Previous Next

To add a comment to this bug, you must first unarchive it, by sending
a message to control AT debbugs.gnu.org, with unarchive 39944 in the body.
You can then email your comments to 39944 AT debbugs.gnu.org in the normal way.

Toggle the display of automated, internal messages from the tracker.

Message #5 received at submit <at> debbugs.gnu.org (full text, mbox):

From: Eli Zaretskii <eliz <at> gnu.org>
To: bug-gnu-emacs <at> gnu.org
Subject: 27.0.90; JIT Stealth timer errors
Date: Fri, 06 Mar 2020 12:01:46 +0200

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

Message #8 received at 39944 <at> debbugs.gnu.org (full text, mbox):

From: Eli Zaretskii <eliz <at> gnu.org>
To: 39944 <at> debbugs.gnu.org
Subject: Re: bug#39944: 27.0.90; JIT Stealth timer errors
Date: Fri, 06 Mar 2020 12:06:03 +0200

> Date: Fri, 06 Mar 2020 12:01:46 +0200
> From: Eli Zaretskii <eliz <at> 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])

Message #11 received at 39944 <at> debbugs.gnu.org (full text, mbox):

From: Eli Zaretskii <eliz <at> gnu.org>
To: 39944 <at> debbugs.gnu.org
Subject: Re: bug#39944: 27.0.90; JIT Stealth timer errors
Date: Fri, 06 Mar 2020 12:16:07 +0200

> Date: Fri, 06 Mar 2020 12:06:03 +0200
> From: Eli Zaretskii <eliz <at> gnu.org>
> 
> > Date: Fri, 06 Mar 2020 12:01:46 +0200
> > From: Eli Zaretskii <eliz <at> 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.

Message #14 received at 39944 <at> debbugs.gnu.org (full text, mbox):

From: Eli Zaretskii <eliz <at> gnu.org>
To: Paul Eggert <eggert <at> cs.ucla.edu>
Cc: 39944 <at> debbugs.gnu.org
Subject: Re: bug#39944: 27.0.90; JIT Stealth timer errors
Date: Fri, 06 Mar 2020 18:11:14 +0200

> Date: Fri, 06 Mar 2020 12:16:07 +0200
> From: Eli Zaretskii <eliz <at> 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)

Message #17 received at 39944 <at> debbugs.gnu.org (full text, mbox):

From: Paul Eggert <eggert <at> cs.ucla.edu>
To: Eli Zaretskii <eliz <at> gnu.org>
Cc: 39944 <at> debbugs.gnu.org
Subject: Re: bug#39944: 27.0.90; JIT Stealth timer errors
Date: Sat, 7 Mar 2020 10:02:28 -0800

[Message part 1 (text/plain, inline)]

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.

[0001-Fix-bug-with-JIT-stealth-timers.patch (text/x-patch, attachment)]

Message #20 received at 39944 <at> debbugs.gnu.org (full text, mbox):

From: Eli Zaretskii <eliz <at> gnu.org>
To: Paul Eggert <eggert <at> cs.ucla.edu>
Cc: 39944 <at> debbugs.gnu.org
Subject: Re: bug#39944: 27.0.90; JIT Stealth timer errors
Date: Sat, 07 Mar 2020 20:29:47 +0200

> Cc: 39944 <at> debbugs.gnu.org
> From: Paul Eggert <eggert <at> 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).

Message #23 received at 39944 <at> debbugs.gnu.org (full text, mbox):

From: Paul Eggert <eggert <at> cs.ucla.edu>
To: Eli Zaretskii <eliz <at> gnu.org>
Cc: 39944 <at> debbugs.gnu.org
Subject: Re: bug#39944: 27.0.90; JIT Stealth timer errors
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. 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.

Message #26 received at 39944 <at> debbugs.gnu.org (full text, mbox):

From: Eli Zaretskii <eliz <at> gnu.org>
To: Paul Eggert <eggert <at> cs.ucla.edu>
Cc: 39944 <at> debbugs.gnu.org
Subject: Re: bug#39944: 27.0.90; JIT Stealth timer errors
Date: Sun, 08 Mar 2020 17:10:01 +0200

> From: Paul Eggert <eggert <at> cs.ucla.edu>
> Cc: 39944 <at> 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.

Message #29 received at 39944 <at> debbugs.gnu.org (full text, mbox):

From: Lars Ingebrigtsen <larsi <at> gnus.org>
To: Eli Zaretskii <eliz <at> gnu.org>
Cc: Paul Eggert <eggert <at> cs.ucla.edu>, 39944 <at> debbugs.gnu.org
Subject: Re: bug#39944: 27.0.90; JIT Stealth timer errors
Date: Sun, 20 Sep 2020 10:33:09 +0200

Eli Zaretskii <eliz <at> 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

Previous Next

GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.