bug#66096: High CPU usage, basically runaway emacs with visit to bidi_cache_search on and off?

["ISHIKAWA,chiaki" <ishikawa@yk.rim.or.jp>]

Oh, I now notice that you are saying if resize_echo_area_exactly is 
always there, the backtraces won't help much.
Tough.
I think the routines called by resize_echo_area_exactly do not change 
the environeent to satisfy what resize_echo_area_exactly wamts, but
I think that will need detailed debugging.

Unfortunately, the problem did not recur yesterday afternoon and I could 
edit the file after "recover-file".

I will try to create more meaningful debug information when something 
similar happens.
It was really the first time in a few years when emacs could not be 
interrupted by control-G.
So, I am not sure if I hit the right condition easily.

TIA

Chiaki

On 2023/09/20 16:09, ISHIKAWA,chiaki wrote:
> On 2023/09/19 20:04, Eli Zaretskii wrote:
>>> Cc: "ishikawa, chiaki" <ishikawa@yk.rim.or.jp>
>>> Date: Tue, 19 Sep 2023 13:12:33 +0900
>>> From: "ISHIKAWA,chiaki" <ishikawa@yk.rim.or.jp>
>>>
>>> High CPU usage, basically runaway emacs with visit to bidi_cache_search
>>> on and off?
>>>
>>> Hi,
>>>
>>> Environment:
>>> OS GNU/Debian Linux  X86_64
>>> Emacs version
>>> GNU Emacs 29.1 (build 1, x86_64-pc-linux-gnu, GTK+ Version 3.24.38,
>>> cairo version 1.16.0) of 2023-08-01
>>> I compiled emacs using gcc.
>>>
>>> Has anyone seen emacs 29.1 spending CPU way too high, basically went
>>> into an infinite loop of some sort, and could not be interrupted by
>>> Control-G?  Basically it is in a runaway state.
>>> I found that the stacktraces show that bidi_cache_search
>>> and friends are visited now and then.  It is not the recursive blowup
>>> probably since the stack depth is quite limited during my observation.
>>>
>>>
>>> I have experienced this issue this morning.  Observing the stack
>>> backtrace by monitoring the runaway emacs using gdb, I was surprised
>>> to see many appearances of bidi_cache_search that were observed from
>>> time to time while I do control-C to stop emacs and monitor
>>> stacktrace, and the continue for a few seconds, and interrupt it again
>>> with control-C.  After letting emacs run in this manner for about 5
>>> minutes, I had tp kill emacs.  I had to edit the file by a deadline and
>>> could not continue debugging. :-(
>>>
>>> At the end is a single stacktrace with bidi_cache_search at the top.
>>> I have seen this occurring multiple times. My hitting control-C to 
>>> emacs
>>> to enter gdb interaction means that the chance of hitting a particular
>>> stacktrace pattern is small and seeing the same pattern multiple times
>>> means that that pattern happens quite often.
>> The backtrace shows we were resizing the mini-window, but it doesn't
>> tell where and why we were looping.
>>
>> (The bidi_cache_search part is probably a red herring: that function
>> is indeed called very frequently when Emacs performs display and
>> layout calculations -- which is not surprising, since that's why the
>> bidi cache exists: to provide cache hits whenever possible.)
>>
>> So it is important to have a file and the sequence of commands that
>> trigger this.  Please try to produce such a file and a recipe to
>> reproduce the problem.
>>
>> Alternatively, you can use the technique described in etc/DEBUG for
>> finding where Emacs loops, see there under "If the symptom of the bug
>> is that Emacs fails to respond".  I think even if you do discover
>> where it loops, we'd need an example file to see why, though.
>>
>>> I have a dozen or so more different stacktraces during gdb monitoring.
>>> If someone wants to see the log, I can post it.
>>> What is the preferred URL where I can paste the whole gdb session?
>> You can post them here, perhaps compressed.  However, if they are all
>> of the same kind, i.e. start with resize_echo_area_exactly, then I
>> don't think more backtraces alone will help.
>>
>> Thanks.
>>
> Thank you for your comment.
>
> There seem to be enough variation of the stacktrace patterns.
>
> I am attaching the gdb session file as zipped archive.
> As you suggested, it seems Emacs is trying to resize echo area, and is 
> looping somehow.
> resize_echo_area_exactly () seems to be always there.
> It could be that it was trying to dump the S-expression that encodes 
> the latest GC information after each GC.
>
> I have the following code snippet to monitor GC issues on my PC for 
> quite sometime.
> But I have not seen this particular problem before.
> The long pause I have seen before was strictly in GC-related routines.
>
> (setq my-gc-statistics (make-vector 30 nil))
>
> ;;; The element is
> ;;; (append (memory-use-counts) (list gc-elapsed gcs-done))
> ;;; Each time the following function is called, the
> ;;; elements in the array is shifted toward the end.
> ;;; Use (message "%S" my-gc-statistics) to force the
> ;;; recording of my-gc-statistics value in *Messages* buffer for later 
> analysis.
>
>
> (defun update-my-gc-statistics ()
>   (let ((i 28))
>     (progn
>      ;;; very unlike Lisp
>      (while (<= 0 i)
>        (progn (aset my-gc-statistics (+ 1 i) (aref my-gc-statistics i))
>              (setq i (- i 1) )))
>      (aset my-gc-statistics 0
>            (append (memory-use-counts) (list gc-elapsed gcs-done)))
>      ;;; print the latest one last so that I can see the glimpse in 
> the narrow
>      ;;; output window.
>      (message "%S\n%S" (current-time-string) (pp (reverse 
> my-gc-statistics))))))
>
> (setq post-gc-hook 'update-my-gc-statistics)
>
> For example, in one place, I see
> #0  0x0000556f1905be9e in string_char_and_length
>     (length=<synthetic pointer>, p=0x556f20d8a3d8 " 70337 417360 
> 2.323839139 50)\n (99058573 3875 59193441 34949 11084445 70337 417401 
> 2.391973008 51)]\n\"") at 
> /home/ishikawa/repos/emacs-29.1/src/character.h:375
>
> And that string is probably   from (append (memory-use-counts) (list 
> gc-elapsed gcs-done))
>
> Also I see recursive_edit at the bottom of the stakctrace.
> Not sure why. Maybe I was doing some error recovery of Japanese input?
>
>
> In any case, Emacs should not enter a state that cannot be interrupted 
> by CONTROL-G for a long time IMHO.
> (Or was it that the processing of control-G somehow resulted in the 
> effort to widen echo area and emacs failed?)
>
> TIA
>
>
> Chiaki