Subject: bug#76609: 31.0.50; The 0.1s repeat timer is very CPU-intensive; it might be a bug?

From: Eval Exec <[email-masked]>
Date: Thu, 27 Feb 2025 23:05:03 +0800

I created test.el:
(defun exec/emacs-lisp-machine-update()
  ;; do nothing
)
(progn
  (defvar exec/emacs-lisp-machine-timer nil)
  (when (timerp exec/emacs-lisp-machine-timer)
  (cancel-timer exec/emacs-lisp-machine-timer))
  (setq exec/emacs-lisp-machine-timer
  (run-with-timer 0.0 0.00001 'exec/emacs-lisp-machine-update))
)

then build emacs with --enable-profiling, then :

./bin/emacs -Q -l test.el

will get a gmon.out file, then I found:

❯ gprof ./bin/emacs gmon.out
Flat profile:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total
 time   seconds   seconds    calls  Ts/call  Ts/call  name
 48.00      0.84     0.84
process_mark_stack.lto_priv.0
  5.71      0.94     0.10                             mark_char_table
  4.00      1.01     0.07                             bidi_resolve_explicit
  2.86      1.06     0.05                             gui_produce_glyphs
  2.29      1.10     0.04
face_before_or_after_it_pos.lto_priv.0
  1.71      1.13     0.03                             Ffuncall
  1.71      1.16     0.03
move_it_in_display_line_to.constprop.1
  1.14      1.18     0.02                             Fassq
  1.14      1.20     0.02                             Fcommand_modes
  1.14      1.22     0.02                             bidi_level_of_next_char
  1.14      1.24     0.02                             bidi_move_to_visually_next
  1.14      1.26     0.02                             bidi_resolve_neutral
  1.14      1.28     0.02                             find_interval
  1.14      1.30     0.02                             ftcrfont_close.lto_priv.0
  1.14      1.32     0.02                             funcall_general
  1.14      1.34     0.02                             set_buffer_internal_2
  0.57      1.35     0.01                             Fcons
  0.57      1.36     0.01                             Fminus
  0.57      1.37     0.01
Fnext_single_property_change
  0.57      1.38     0.01                             _init
  0.57      1.39     0.01                             assq_no_quit
  0.57      1.40     0.01                             bidi_cache_iterator_state
  0.57      1.41     0.01
bidi_cache_search.constprop.0
  0.57      1.42     0.01                             bidi_explicit_dir_char
  0.57      1.43     0.01                             bidi_fetch_char
  0.57      1.44     0.01
composition_compute_stop_pos
  0.57      1.45     0.01
compute_line_metrics.lto_priv.0
  0.57      1.46     0.01                             display_line.lto_priv.0
  0.57      1.47     0.01                             do_symval_forwarding
  0.57      1.48     0.01                             face_for_char
  0.57      1.49     0.01                             fill_glyph_string
  0.57      1.50     0.01                             fix_position
  0.57      1.51     0.01
ftcrfont_encode_char.lto_priv.0
  0.57      1.52     0.01                             ftcrfont_glyph_extents
  0.57      1.53     0.01                             get_keyelt.constprop.0
  0.57      1.54     0.01
get_lface_attributes.lto_priv.0
  0.57      1.55     0.01                             indirect_function
  0.57      1.56     0.01
internal_equal_1.lto_priv.0
  0.57      1.57     0.01                             make_interval
  0.57      1.58     0.01
map_sub_char_table.lto_priv.0
  0.57      1.59     0.01
mark_stack_push_value.lto_priv.0
  0.57      1.60     0.01
mark_window_display_accurate_1
  0.57      1.61     0.01                             pgtk_set_glyph_string_gc
  0.57      1.62     0.01
pgtk_window_is_of_frame_recursive.lto_priv.0
  0.57      1.63     0.01                             plist_get
  0.57      1.64     0.01
produce_special_glyphs.lto_priv.0
  0.57      1.65     0.01
set_cursor_from_row.lto_priv.0
  0.57      1.66     0.01
set_iterator_to_next.lto_priv.0
  0.57      1.67     0.01                             specbind
  0.57      1.68     0.01                             start_display
  0.57      1.69     0.01                             substring_both
  0.57      1.70     0.01
swap_in_symval_forwarding.lto_priv.0
  0.57      1.71     0.01                             sweep_strings.lto_priv.0
  0.57      1.72     0.01                             sweep_vectors.lto_priv.0
  0.57      1.73     0.01                             time_arith.lto_priv.0
  0.57      1.74     0.01
traverse_intervals.constprop.0
  0.57      1.75     0.01                             unbind_to.constprop.0

 %         the percentage of the total running time of the
time       program used by this function.

cumulative a running sum of the number of seconds accounted
 seconds   for by this function and those listed above it.

 self      the number of seconds accounted for by this
seconds    function alone.  This is the major sort for this
           listing.

calls      the number of times this function was invoked, if
           this function is profiled, else blank.

 self      the average number of milliseconds spent in this
ms/call    function per call, if this function is profiled,
           else blank.

 total     the average number of milliseconds spent in this
ms/call    function and its descendents per call, if this
           function is profiled, else blank.

name       the name of the function.  This is the minor sort
           for this listing. The index shows the location of
           the function in the gprof listing. If the index is
           in parenthesis it shows where it would appear in
           the gprof listing if it were to be printed.

Copyright (C) 2012-2024 Free Software Foundation, Inc.

Copying and distribution of this file, with or without modification,
are permitted in any medium without royalty provided the copyright
notice and this notice are preserved.

On Thu, Feb 27, 2025 at 10:38 PM Eval Exec <[email-masked]> wrote:
>
> Compare to a bash script:
> while true; do
>   sleep 0.1;
>    date
> done
>
> above script have 0% CPU usage on my laptop.
>
> change it to 0.0001:
> while true; do
>   sleep 0.0001;
>    date
> done
>
> even 0.0001 s repeat, the bash script only have 4% cpu usage.
>
> So I think a 0.1s repeat timer in Emacs consume 45% is very surprise.
> I think maybe we should improve the timer performance
>
> On Thu, Feb 27, 2025 at 10:34 PM Eval Exec <[email-masked]> wrote:
> >
> > 45% CPU for a 0.1s repeating timer does seem surprisingly high. Is
> > there a way we can optimize this, given the frequent timer
> > invocations?
> >
> > On Thu, Feb 27, 2025 at 10:27 PM Eli Zaretskii <[email-masked]> wrote:
> > >
> > > > From: Eval Exec <[email-masked]>
> > > > Date: Thu, 27 Feb 2025 21:55:40 +0800
> > > >
> > > > I a 0.1 s repeat timer in emacs -Q, then Emacs's the cpu usage is 30% ~
> > > > 70%.
> > > > I think it's a bug.
> > >
> > > I get around 45% with this, but why do you consider this a bug?  Your
> > > timer function perhaps does nothing, but the timer machinery is
> > > invoked every 100 msec, and it does consume CPU.
> > >
> > > in addition, when you have a high-frequency timer, the Emacs idle loop
> > > is much more expensive, because instead of waiting inside pselect, it
> > > runs all the loop code every 100 msec.
> > >
> > > Maybe I'm missing something, but I don't see a bug here.