Subject: bug#58558: 29.0.50; re-search-forward is slow in some buffers

From: Ihor Radchenko <[email-masked]>
Date: Tue, 13 Dec 2022 18:40:17 +0000

Stefan Monnier <[email-masked]> writes:

>> The benchmark itself does not trigger the breakpoint.
>
> Does that mean that `Fmatch_data` is not called during a single
> `re-search-forward` (not a surprise: you'd need to put a breakpoint on
> `build_marker` to see the markers built by `buf_bytepos_to_charpos`)
> but is called between `re-search-forward`, or that it's not called at
> all during the whole benchmark where you perform several
> `re-search-forward` which grow progressively slower?

I do the benchmark via
M-:
(benchmark-progn (goto-char (point-min)) (while (re-search-forward yant/re nil t))) 
<RET>

The breakpoint triggers after the minibuffer outputs the elapsed time.
During redisplay, AFAIU.

> If it's the latter, then those calls can't explain the slowdown, right?

The slowdown manifests by increasing elapsed time upon subsequent
benchmark calls like the above. So, redisplay may or may not be a part
of it.

I tried to run 

(progn (benchmark-progn (goto-char (point-min)) (while (re-search-forward yant/re nil t))) (benchmark-progn (goto-char (point-min)) (while (re-search-forward yant/re nil t))))

4 times:

Elapsed time: 16.399824s
Elapsed time: 17.009694s
nil
Elapsed time: 18.187187s
Elapsed time: 18.597610s
nil
Elapsed time: 18.851388s
Elapsed time: 19.593968s
nil
Elapsed time: 20.194616s
Elapsed time: 20.414686s
nil

Though message may still trigger the redisplay. Not sure if this small
test really reveals anything useful.

Now, with (garbage-collect):

(progn (benchmark-progn (goto-char (point-min)) (while (re-search-forward yant/re nil t))) (garbage-collect) (benchmark-progn (goto-char (point-min)) (while (re-search-forward yant/re nil t))))

Elapsed time: 20.576637s
<GC>
Elapsed time: 15.734101s
Elapsed time: 16.101646s
<GC>
Elapsed time: 16.179796s
Elapsed time: 16.545040s
<GC>
Elapsed time: 16.365847s
Elapsed time: 16.842143s
<GC>
Elapsed time: 16.726615s

So, GC does help somewhat.

Then, if I kill and re-open the Org buffer:

Elapsed time: 72.847256s ;; <- Org just did a bunch of re-search for initial folding and setup
<GC>
Elapsed time: 4.864642s

re-open again, but GC before running the benchmark:

<GC>
Elapsed time: 4.884221s
<GC>
Elapsed time: 4.368755s

>> If I read the backtrace correctly, something in my custom mode-line is
>> triggering Fmatch_data that creates markers.
>
> The most common calls to `match-data` are from `save-match-data`.
> And most uses of `save-match-data` are ill-advised (as the docstring
> explains `save-match-data' should be used to save *your* match data
> rather than your caller's match data), so you might like to double check
> whether that call to `match-data` can be eliminated altogether.

This is coming from s.el. In any case, this implementation detail did
not change as I switched from Emacs 28 to Emacs 29. It is Emacs doing
something less efficiently here.

What I can try to do is replacing s-* functions in my mode-line with
built-ins. Will it help debugging this issue?

-- 
Ihor Radchenko // yantar92,
Org mode contributor,
Learn more about Org mode at <https://orgmode.org/>.
Support Org development at <https://liberapay.com/org-mode>,
or support my work at <https://liberapay.com/yantar92>