Existing redisplay profiling tool?

Existing redisplay profiling tool?

[Yuan Fu]

Hi guys,

I’m doing some optimization for tree-sitter font-lock, and want to measure the difference in a real editing session (rather than fontifying the whole buffer 10 times). I’m sure there’s some tool for measuring time spent in redisplay some where, but couldn’t find anything poking around.

Thanks,
Yuan

Re: Existing redisplay profiling tool?

[Eli Zaretskii]

> From: Yuan Fu <casouri@gmail.com>
> Date: Sat, 14 Sep 2024 11:20:15 -0700
> 
> I’m doing some optimization for tree-sitter font-lock, and want to measure the difference in a real editing session (rather than fontifying the whole buffer 10 times). I’m sure there’s some tool for measuring time spent in redisplay some where, but couldn’t find anything poking around.

How about using the scrolling benchmark through xdisp.c while
profiling?

(defun scroll-up-benchmark ()
  (interactive)
  (let ((oldgc gcs-done)
        (oldtime (float-time)))
    (condition-case nil (while t (scroll-up) (redisplay))
      (error (message "GCs: %d Elapsed time: %f seconds"
                      (- gcs-done oldgc) (- (float-time) oldtime))))))

Evaluate the above, then turn on profiling, then type
"M-x scroll-up-benchmark RET" with point at beginning
of buffer that visits xdisp.c under c-ts-mode.

Re: Existing redisplay profiling tool?

[Yuan Fu]

> On Sep 14, 2024, at 12:10 PM, Eli Zaretskii <eliz@gnu.org> wrote:
> 
>> From: Yuan Fu <casouri@gmail.com>
>> Date: Sat, 14 Sep 2024 11:20:15 -0700
>> 
>> I’m doing some optimization for tree-sitter font-lock, and want to measure the difference in a real editing session (rather than fontifying the whole buffer 10 times). I’m sure there’s some tool for measuring time spent in redisplay some where, but couldn’t find anything poking around.
> 
> How about using the scrolling benchmark through xdisp.c while
> profiling?
> 
> (defun scroll-up-benchmark ()
>  (interactive)
>  (let ((oldgc gcs-done)
>        (oldtime (float-time)))
>    (condition-case nil (while t (scroll-up) (redisplay))
>      (error (message "GCs: %d Elapsed time: %f seconds"
>                      (- gcs-done oldgc) (- (float-time) oldtime))))))
> 
> Evaluate the above, then turn on profiling, then type
> "M-x scroll-up-benchmark RET" with point at beginning
> of buffer that visits xdisp.c under c-ts-mode.

Thanks! I’m hoping to measure the perceived responsiveness when typing text in the buffer, so here’s what I came up with:

(let ((prev-time (current-time))
      (measurements nil))
  (dotimes (_ 100)
    (insert "s")
    (redisplay)
    (push (float-time (time-subtract (current-time) prev-time))
          measurements)
    (setq prev-time (current-time)))
  (message "Average time: %f"
           (/ (apply #'+ measurements) (length measurements))))

Do you think this accurately measures the redisplay time between each keystroke? (Obviously this doesn’t take account of post-command-hook, I only want to measure repose & redisplay here.)

If that’s an accurate measurements, then my optimization doesn’t make any significant difference :-)
In xdisp.c, inserting 100 “s” takes about 17.8ms per “keystroke” on average. With optimization it’s about 16.7ms, not much difference.

Obviously the time differs depending on where are you inserting the “s”, but I tried a few places (close to beginning of buffer, close to end, inside a function, outside a function, etc), and the measurements doesn’t vary too much (12–16ms with optimization on)

I also measured a base performance by enabling fundamental-mode in xdisp.c. It takes about 2.2ms between each “keystroke”.

In a very small file, the average time between each “keystroke” is 3.2ms and 3.5ms, for optimized and unoptimized run respectively.

Finally, c-mode in xdisp.c takes about 10.7ms per “keystroke” ;-)

I guess the takeaway is a) my new optimization doesn’t do anything, and b) tree-sitter font-lock doesn’t add human-perceivable latency when typing.

Yuan

My measurements:

xdisp.c:
optimization off: Average time: 0.017755 -> 17.8ms
optimization  on: Average time: 0.016701 -> 16.7ms
fundamental mode: Average time: 0.002188 -> 2.2ms

optimization on w/ post-command-hook: Average time: 0.033086 -> 33.1ms


small file:
optimization  on: Average time: 0.003207 -> 3.2ms
optimization off: Average time: 0.003473 -> 3.5ms

optimization on w/ post-command-hook: Average time: 0.013553 -> 13.6ms

c-mode:
xdisp.c : Average time: 0.010691 -> 10.7ms
small file: Average time: 0.005141 -> 5.1ms

Re: Existing redisplay profiling tool?

[Eli Zaretskii]

> From: Yuan Fu <casouri@gmail.com>
> Date: Sun, 15 Sep 2024 23:16:48 -0700
> Cc: emacs-devel@gnu.org
> 
> > How about using the scrolling benchmark through xdisp.c while
> > profiling?
> > 
> > (defun scroll-up-benchmark ()
> >  (interactive)
> >  (let ((oldgc gcs-done)
> >        (oldtime (float-time)))
> >    (condition-case nil (while t (scroll-up) (redisplay))
> >      (error (message "GCs: %d Elapsed time: %f seconds"
> >                      (- gcs-done oldgc) (- (float-time) oldtime))))))
> > 
> > Evaluate the above, then turn on profiling, then type
> > "M-x scroll-up-benchmark RET" with point at beginning
> > of buffer that visits xdisp.c under c-ts-mode.
> 
> Thanks! I’m hoping to measure the perceived responsiveness when typing text in the buffer, so here’s what I came up with:
> 
> (let ((prev-time (current-time))
>       (measurements nil))
>   (dotimes (_ 100)
>     (insert "s")
>     (redisplay)
>     (push (float-time (time-subtract (current-time) prev-time))
>           measurements)
>     (setq prev-time (current-time)))
>   (message "Average time: %f"
>            (/ (apply #'+ measurements) (length measurements))))
> 
> Do you think this accurately measures the redisplay time between each keystroke? (Obviously this doesn’t take account of post-command-hook, I only want to measure repose & redisplay here.)

I don't understand why you measure only insertion of a single
character.  This kind of change to buffer text is so frequent that it
has special optimizations in the display engine, and you might be
measuring only those special optimizations.

I proposed a scrolling benchmark because it executes the font-lock
code many times, and is more expensive than insertion of a single
character.  You might as well try both, and could learn different
things from each other.

A variant of the above scrolling benchmark is scrolling by many lines
in one go (it causes a larger mismatch between the previous and the
current window, so redisplay is forced to use yet another code path
for that):

(defun scroll-up-by-40-benchmark ()
  (interactive)
  (let ((oldgc gcs-done)
        (oldtime (float-time)))
    (condition-case nil (while t (scroll-up 40) (redisplay))
      (error (message "GCs: %d Elapsed time: %f seconds"
                      (- gcs-done oldgc) (- (float-time) oldtime))))))

> If that’s an accurate measurements, then my optimization doesn’t make any significant difference :-)
> In xdisp.c, inserting 100 “s” takes about 17.8ms per “keystroke” on average. With optimization it’s about 16.7ms, not much difference.

That's because redisplay is careful to redraw only a single screen
line when a single character is added.  I'm not sure this is the only
situation that is interesting for you, but then I don't really know
what you are trying to optimize.

> I guess the takeaway is a) my new optimization doesn’t do anything, and b) tree-sitter font-lock doesn’t add human-perceivable latency when typing.

Try the other benchmarks, and maybe you will arrive at different
conclusions.

Re: Existing redisplay profiling tool?

[Yuan Fu]

> On Sep 16, 2024, at 5:19 AM, Eli Zaretskii <eliz@gnu.org> wrote:
> 
>> From: Yuan Fu <casouri@gmail.com>
>> Date: Sun, 15 Sep 2024 23:16:48 -0700
>> Cc: emacs-devel@gnu.org
>> 
>>> How about using the scrolling benchmark through xdisp.c while
>>> profiling?
>>> 
>>> (defun scroll-up-benchmark ()
>>> (interactive)
>>> (let ((oldgc gcs-done)
>>>       (oldtime (float-time)))
>>>   (condition-case nil (while t (scroll-up) (redisplay))
>>>     (error (message "GCs: %d Elapsed time: %f seconds"
>>>                     (- gcs-done oldgc) (- (float-time) oldtime))))))
>>> 
>>> Evaluate the above, then turn on profiling, then type
>>> "M-x scroll-up-benchmark RET" with point at beginning
>>> of buffer that visits xdisp.c under c-ts-mode.
>> 
>> Thanks! I’m hoping to measure the perceived responsiveness when typing text in the buffer, so here’s what I came up with:
>> 
>> (let ((prev-time (current-time))
>>      (measurements nil))
>>  (dotimes (_ 100)
>>    (insert "s")
>>    (redisplay)
>>    (push (float-time (time-subtract (current-time) prev-time))
>>          measurements)
>>    (setq prev-time (current-time)))
>>  (message "Average time: %f"
>>           (/ (apply #'+ measurements) (length measurements))))
>> 
>> Do you think this accurately measures the redisplay time between each keystroke? (Obviously this doesn’t take account of post-command-hook, I only want to measure repose & redisplay here.)
> 
> I don't understand why you measure only insertion of a single
> character.  This kind of change to buffer text is so frequent that it
> has special optimizations in the display engine, and you might be
> measuring only those special optimizations.

Personally, I’ve had instances where typing was sluggish and I have suspected tree-sitter, but of course it always turns out to be post-command-hook. I’m just curious how long it takes Emacs to be ready to process the next input after each keystroke when using tree-sitter and not using tree-sitter, and with or without my font-lock optimization.

Work done by display engine isn’t really what I’m after—I’m sure it’s optimized and fast—it’s the font-lock part. After every keystroke, tree-sitter needs to reparse every parser, and update ranges for all the embedded parsers. Then it needs to go over treesit-font-lock-settings to fontify the changed range.

> 
> I proposed a scrolling benchmark because it executes the font-lock
> code many times, and is more expensive than insertion of a single
> character.  You might as well try both, and could learn different
> things from each other.

Scrolling benchmark measures scrolling, but I know scrolling is pretty fast and I’ve never had problem with it. Also no reparse and parser range update happens during scrolling, while when typing they happen after every keystroke.

> 
> A variant of the above scrolling benchmark is scrolling by many lines
> in one go (it causes a larger mismatch between the previous and the
> current window, so redisplay is forced to use yet another code path
> for that):
> 
> (defun scroll-up-by-40-benchmark ()
>  (interactive)
>  (let ((oldgc gcs-done)
>        (oldtime (float-time)))
>    (condition-case nil (while t (scroll-up 40) (redisplay))
>      (error (message "GCs: %d Elapsed time: %f seconds"
>                      (- gcs-done oldgc) (- (float-time) oldtime))))))
> 
>> If that’s an accurate measurements, then my optimization doesn’t make any significant difference :-)
>> In xdisp.c, inserting 100 “s” takes about 17.8ms per “keystroke” on average. With optimization it’s about 16.7ms, not much difference.
> 
> That's because redisplay is careful to redraw only a single screen
> line when a single character is added.  I'm not sure this is the only
> situation that is interesting for you, but then I don't really know
> what you are trying to optimize.

I’m trying to optimize (or at least verify) typing delay. I want to measure how long it takes Emacs to process everything and be ready for next input after each keystroke.

> 
>> I guess the takeaway is a) my new optimization doesn’t do anything, and b) tree-sitter font-lock doesn’t add human-perceivable latency when typing.
> 
> Try the other benchmarks, and maybe you will arrive at different
> conclusions.

Re: Existing redisplay profiling tool?

[Eli Zaretskii]

> From: Yuan Fu <casouri@gmail.com>
> Date: Mon, 16 Sep 2024 19:49:28 -0700
> Cc: emacs-devel@gnu.org
> 
> > I don't understand why you measure only insertion of a single
> > character.  This kind of change to buffer text is so frequent that it
> > has special optimizations in the display engine, and you might be
> > measuring only those special optimizations.
> 
> Personally, I’ve had instances where typing was sluggish and I have suspected tree-sitter, but of course it always turns out to be post-command-hook. I’m just curious how long it takes Emacs to be ready to process the next input after each keystroke when using tree-sitter and not using tree-sitter, and with or without my font-lock optimization.

User can type keys other than self-inserting characters, right?  They
could type arrow keys, for example, or PgUp/PgDn.

> Work done by display engine isn’t really what I’m after—I’m sure it’s optimized and fast—it’s the font-lock part. After every keystroke, tree-sitter needs to reparse every parser, and update ranges for all the embedded parsers. Then it needs to go over treesit-font-lock-settings to fontify the changed range.

Font lock is invoked by the display engine, so it is somewhat
relevant, I think.

As I said, I don't really know what you are trying to optimize, but if
you only are interested in reparsing of the buffer text by
tree-sitter, there could be changes other than insertion f a single
character.  For example, pasting several code lines is a very frequent
operation in editing program code.  Likewise deleting some significant
portion of a buffer.  These are more expensive from the redisplay POV,
and also from font-lock POV, I think.

> > I proposed a scrolling benchmark because it executes the font-lock
> > code many times, and is more expensive than insertion of a single
> > character.  You might as well try both, and could learn different
> > things from each other.
> 
> Scrolling benchmark measures scrolling, but I know scrolling is pretty fast and I’ve never had problem with it. Also no reparse and parser range update happens during scrolling, while when typing they happen after every keystroke.

OK, but even if you are only interested in reparsing, there's more
than just inserting a single character.  And scrolling does invoke
tree-sitter queries, doesn't it -- perhaps that is of interest as
well?

Anyway, I'm just throwing around ideas, feel free to ignore if they
are not relevant to your investigation.