bug#20404: 25.0.50; Sometimes no fontification with jit-lock-defer-time

[Tassilo Horn <tsdh@gnu.org>]

Eli Zaretskii <eliz@gnu.org> writes:

>> From: Tassilo Horn <tsdh@gnu.org>
>> Cc: 20404@debbugs.gnu.org
>> Date: Thu, 23 Apr 2015 07:59:15 +0200
>> 
>> Eli Zaretskii <eliz@gnu.org> writes:
>> 
>> > So you are saying that something prevents the timer to run at the
>> > prescribed time?
>> 
>> That seems to be the case.
>
> It can also be that Emacs doesn't become idle for some reason.
>
>> > I suggest to add trace printf's in the code that traverses the
>> > idle-timers' list, and see why this timer doesn't run on time.
>> 
>> That would be
>> 
>>   static struct timespec
>>   timer_check_2 (Lisp_Object timers, Lisp_Object idle_timers)
>> 
>> right?
>
> Yes.
>
>> +	  if (ripe)
>> +	    {
>> +	      printf("Idle timer calling %s is ripe.", AREF (5, chosen_timer));
>> +	    }
>>  	}
>>  
>>        /* If timer is ripe, run it if it hasn't been run.  */
>> --8<---------------cut here---------------end--------------->8---
>> 
>> I think the problem is that the AREF returns the timer's function or
>> maybe the symbol whose function definition is the timer's function.
>
> Yes, you cannon printf a Lisp object with %s.
>
>> How do I get the function's name in order to print that?
>
> Try SDATA (SYMBOL_NAME (AREF (5, chosen_timer))).

That works although you have to add more checks for lambdas, etc.  So
now I use this:

--8<---------------cut here---------------start------------->8---
diff --git a/src/keyboard.c b/src/keyboard.c
index 068a47c..fe906b0 100644
--- a/src/keyboard.c
+++ b/src/keyboard.c
@@ -4410,6 +4410,24 @@ decode_timer (Lisp_Object timer, struct timespec *result)
    In that case we return 0 to indicate that a new timer_check_2 call
    should be done.  */
 
+void print_timer(Lisp_Object chosen_timer, const char* kind) {
+  const char* timer_fn_name = "<no function>";
+  const Lisp_Object fn = AREF (chosen_timer, 5);
+  if (fn) {
+    timer_fn_name = "<anon fn>";
+    if (SYMBOLP (fn)) {
+      const Lisp_Object sn = SYMBOL_NAME (fn);
+      if (sn) {
+	timer_fn_name = SDATA (sn);
+      }
+    }
+  }
+  printf("%s timer calling %s is ripe.\n",
+	 kind, timer_fn_name);
+}
+
+int myCounter = 0;
+
 static struct timespec
 timer_check_2 (Lisp_Object timers, Lisp_Object idle_timers)
 {
@@ -4419,6 +4437,8 @@ timer_check_2 (Lisp_Object timers, Lisp_Object idle_timers)
   Lisp_Object chosen_timer;
   struct gcpro gcpro1;
 
+  printf ("timer_check2 () %d\n", myCounter++);
+  
   nexttime = invalid_timespec ();
 
   chosen_timer = Qnil;
@@ -4506,6 +4526,10 @@ timer_check_2 (Lisp_Object timers, Lisp_Object idle_timers)
 	  timers = XCDR (timers);
 	  difference = timer_difference;
 	  ripe = timer_ripe;
+	  if (ripe)
+	    {
+	      print_timer (chosen_timer, "normal");
+	    }  
 	}
       else
 	{
@@ -4513,6 +4537,10 @@ timer_check_2 (Lisp_Object timers, Lisp_Object idle_timers)
 	  idle_timers = XCDR (idle_timers);
 	  difference = idle_timer_difference;
 	  ripe = idle_timer_ripe;
+	  if (ripe)
+	    {
+	      print_timer (chosen_timer, "idle");
+	    }
 	}
 
       /* If timer is ripe, run it if it hasn't been run.  */
--8<---------------cut here---------------end--------------->8---

And when doing `M-x report-emacs-bug RET bug summary RET`, that's the
output in the period in which the buffer is not fontified.

--8<---------------cut here---------------start------------->8---
normal timer calling blink-cursor-timer-function is ripe.
timer_check2 () 1329
timer_check2 () 1330
timer_check2 () 1331
timer_check2 () 1332
timer_check2 () 1333
timer_check2 () 1334
timer_check2 () 1335
timer_check2 () 1336
timer_check2 () 1337
timer_check2 () 1338
timer_check2 () 1339
timer_check2 () 1340
timer_check2 () 1341
timer_check2 () 1343
timer_check2 () 1344
timer_check2 () 1345
timer_check2 () 1346
timer_check2 () 1348
timer_check2 () 1349
timer_check2 () 1350
timer_check2 () 1351
timer_check2 () 1352
timer_check2 () 1353
timer_check2 () 1354
timer_check2 () 1355
timer_check2 () 1356
timer_check2 () 1357
timer_check2 () 1358
timer_check2 () 1359
timer_check2 () 1360
timer_check2 () 1361
timer_check2 () 1362
timer_check2 () 1363
timer_check2 () 1364
timer_check2 () 1365
timer_check2 () 1366
timer_check2 () 1367
idle timer calling jit-lock-deferred-fontify is ripe.
--8<---------------cut here---------------end--------------->8---

So as you can see, in that period there are many calls of timer_check2()
but none of them select some timer as being ripe.  Neither normal nor
idle timers.  That is, the problem isn't really about deferred
fontification but about timer's not being selected for execution.  That
is, for example the cursor doesn't blink, too, which is another idle
timer that's not run in the period.

Here's the output if I also `trace-redisplay'.

--8<---------------cut here---------------start------------->8---
redisplay_internal 0
trying display optimization 1
0x12b1c30 ( *Minibuf-1*): optimization 1
timer_check2 () 4941
timer_check2 () 4942
timer_check2 () 4943
timer_check2 () 4944
timer_check2 () 4945
timer_check2 () 4946
redisplay_preserve_echo_area (2)
redisplay_internal 0
0x12b0c20 (*unsent mail to bug-gnu-emacs@gnu.org*): same window start
0x12b0c20 (*unsent mail to bug-gnu-emacs@gnu.org*): 1
0x12f8d60 (*Bug Help*): same window start
0x12f8d60 (*Bug Help*): 1
timer_check2 () 4947
redisplay_internal 0
0x12b0c20 (*unsent mail to bug-gnu-emacs@gnu.org*): same window start
0x12b0c20 (*unsent mail to bug-gnu-emacs@gnu.org*): 1
0x12f8d60 (*Bug Help*): same window start
0x12f8d60 (*Bug Help*): 1
timer_check2 () 4948
timer_check2 () 4949
timer_check2 () 4950
timer_check2 () 4951
timer_check2 () 4952
timer_check2 () 4953
timer_check2 () 4954
timer_check2 () 4955
timer_check2 () 4956
timer_check2 () 4957
timer_check2 () 4958
timer_check2 () 4959
timer_check2 () 4960
timer_check2 () 4961
timer_check2 () 4962
timer_check2 () 4963
timer_check2 () 4964
timer_check2 () 4965
timer_check2 () 4966
timer_check2 () 4967
timer_check2 () 4968
timer_check2 () 4969
timer_check2 () 4970
timer_check2 () 4971
timer_check2 () 4972
timer_check2 () 4973
timer_check2 () 4974
timer_check2 () 4975
timer_check2 () 4976
timer_check2 () 4977
redisplay_internal 0
timer_check2 () 4978
timer_check2 () 4979
timer_check2 () 4980
timer_check2 () 4981
timer_check2 () 4982
timer_check2 () 4983
timer_check2 () 4984
redisplay_internal 0
timer_check2 () 4985
timer_check2 () 4986
timer_check2 () 4987
timer_check2 () 4988
idle timer calling jit-lock-deferred-fontify is ripe.
timer_check2 () 4989
timer_check2 () 4990
timer_check2 () 4991
redisplay_preserve_echo_area (2)
redisplay_internal 0
0x12b0c20 (*unsent mail to bug-gnu-emacs@gnu.org*): same window start
0x12b0c20 (*unsent mail to bug-gnu-emacs@gnu.org*): 1
--8<---------------cut here---------------end--------------->8---

HTH,
Tassilo