From mboxrd@z Thu Jan 1 00:00:00 1970 Path: news.gmane.io!.POSTED.blaine.gmane.org!not-for-mail From: "ISHIKAWA,chiaki" Newsgroups: gmane.emacs.bugs Subject: bug#66096: High CPU usage, basically runaway emacs with visit to bidi_cache_search on and off? Date: Wed, 20 Sep 2023 16:16:54 +0900 Message-ID: <4cdbc18c-9e36-4319-921d-fd99302ac957@yk.rim.or.jp> References: <1808d5a1-3ee6-d675-3ad3-c6bcc2fe5e36@yk.rim.or.jp> <834jjqe85z.fsf@gnu.org> <80682fbe-b5ac-4605-b8e5-7baac2d71da5@yk.rim.or.jp> Mime-Version: 1.0 Content-Type: text/plain; charset=UTF-8; format=flowed Content-Transfer-Encoding: 8bit Injection-Info: ciao.gmane.io; posting-host="blaine.gmane.org:116.202.254.214"; logging-data="37820"; mail-complaints-to="usenet@ciao.gmane.io" User-Agent: Mozilla Thunderbird Cc: 66096@debbugs.gnu.org, "ishikawa, chiaki" To: Eli Zaretskii Original-X-From: bug-gnu-emacs-bounces+geb-bug-gnu-emacs=m.gmane-mx.org@gnu.org Wed Sep 20 09:17:27 2023 Return-path: Envelope-to: geb-bug-gnu-emacs@m.gmane-mx.org Original-Received: from lists.gnu.org ([209.51.188.17]) by ciao.gmane.io with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1qirSf-0009Vu-T3 for geb-bug-gnu-emacs@m.gmane-mx.org; Wed, 20 Sep 2023 09:17:25 +0200 Original-Received: from localhost ([::1] helo=lists1p.gnu.org) by lists.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1qirSQ-0007AQ-S6; Wed, 20 Sep 2023 03:17:10 -0400 Original-Received: from eggs.gnu.org ([2001:470:142:3::10]) by lists.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1qirSD-000795-3o for bug-gnu-emacs@gnu.org; Wed, 20 Sep 2023 03:16:58 -0400 Original-Received: from debbugs.gnu.org ([2001:470:142:5::43]) by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.90_1) (envelope-from ) id 1qirS9-00012b-UL for bug-gnu-emacs@gnu.org; Wed, 20 Sep 2023 03:16:54 -0400 Original-Received: from Debian-debbugs by debbugs.gnu.org with local (Exim 4.84_2) (envelope-from ) id 1qirSJ-0002gb-0G for bug-gnu-emacs@gnu.org; Wed, 20 Sep 2023 03:17:03 -0400 X-Loop: help-debbugs@gnu.org Resent-From: "ISHIKAWA,chiaki" Original-Sender: "Debbugs-submit" Resent-CC: bug-gnu-emacs@gnu.org Resent-Date: Wed, 20 Sep 2023 07:17:02 +0000 Resent-Message-ID: Resent-Sender: help-debbugs@gnu.org X-GNU-PR-Message: followup 66096 X-GNU-PR-Package: emacs Original-Received: via spool by 66096-submit@debbugs.gnu.org id=B66096.169519418410261 (code B ref 66096); Wed, 20 Sep 2023 07:17:02 +0000 Original-Received: (at 66096) by debbugs.gnu.org; 20 Sep 2023 07:16:24 +0000 Original-Received: from localhost ([127.0.0.1]:58187 helo=debbugs.gnu.org) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1qirRf-0002fQ-PY for submit@debbugs.gnu.org; Wed, 20 Sep 2023 03:16:24 -0400 Original-Received: from mail06.siriuscloud.jp ([219.118.72.6]:37309) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1qirRc-0002f5-QF for 66096@debbugs.gnu.org; Wed, 20 Sep 2023 03:16:22 -0400 Original-Received: from [192.168.0.77] (M106073032161.v4.enabler.ne.jp [106.73.32.161]) (Authenticated sender: ishikawa@yk.rim.or.jp) by access06.SiriusCloud.jp (Postfix) with ESMTPA id 4Rr8vr3hppz5gSZ; Wed, 20 Sep 2023 16:16:08 +0900 (JST) Authentication-Results: access06.SiriusCloud.jp; dkim=none reason="no signature"; dkim-adsp=none (unprotected policy); dkim-atps=neutral Content-Language: en-US In-Reply-To: <80682fbe-b5ac-4605-b8e5-7baac2d71da5@yk.rim.or.jp> X-BeenThere: debbugs-submit@debbugs.gnu.org X-Mailman-Version: 2.1.18 Precedence: list X-BeenThere: bug-gnu-emacs@gnu.org List-Id: "Bug reports for GNU Emacs, the Swiss army knife of text editors" List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: bug-gnu-emacs-bounces+geb-bug-gnu-emacs=m.gmane-mx.org@gnu.org Original-Sender: bug-gnu-emacs-bounces+geb-bug-gnu-emacs=m.gmane-mx.org@gnu.org Xref: news.gmane.io gmane.emacs.bugs:270907 Archived-At: 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" >>> Date: Tue, 19 Sep 2023 13:12:33 +0900 >>> From: "ISHIKAWA,chiaki" >>> >>> 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=, 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