Package: emacs;
Reported by: Eval Exec <execvy <at> gmail.com>
Date: Thu, 27 Feb 2025 13:57:02 UTC
Severity: normal
Found in version 31.0.50
Message #17 received at 76609 <at> debbugs.gnu.org (full text, mbox):
From: Eval Exec <execvy <at> gmail.com> To: Eli Zaretskii <eliz <at> gnu.org> Cc: 76609 <at> debbugs.gnu.org Subject: Re: bug#76609: 31.0.50; The 0.1s repeat timer is very CPU-intensive; it might be a bug? 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 <execvy <at> gmail.com> 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 <execvy <at> gmail.com> 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 <eliz <at> gnu.org> wrote:
> > >
> > > > From: Eval Exec <execvy <at> gmail.com>
> > > > 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.
GNU bug tracking system
Copyright (C) 1999 Darren O. Benham,
1997,2003 nCipher Corporation Ltd,
1994-97 Ian Jackson.