bug#39413: 26.2; Emacs gets hung

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

[-- Attachment #1: Type: text/plain, Size: 3281 bytes --]

On 2021/08/12 16:10, Eli Zaretskii wrote:
>> Cc: larsi@gnus.org, npostavs@gmail.com, 39413@debbugs.gnu.org,
>>   chiaki.ishikawa@ubin.jp
>> From: "ISHIKAWA,chiaki" <ishikawa@yk.rim.or.jp>
>> Date: Wed, 11 Aug 2021 22:41:56 +0900
>>
>> What about the dump below, which was in the *Messages* buffer following
>> dump I sent.
>> I am afraid I picked up the wrong dump in my previous e-mail.
>>
>> Now, is "gc-elapsed" the elapsed time spent in the GC routine?
>> If so, the two samples at the end of the dump here certainly look
>> suspicious.
> Yes, they show a couple of GCs that took about 150 to 200 sec.  That
> is indeed excessive, but gc-elapsed reports the wall-clock time, not
> the CPU time, so if Emacs wasn't getting processing resources to run,
> which could happen on a stressed system, that could explain the long
> GC times.  Note that other GC cycles, both before and after the 2
> problematic ones, took much less time.  And the statistics returned by
> memory-use-counts doesn't show any excessive number of Lisp objects;
> in fact, my current Emacs session, which runs for 9.5 days, has an
> order of magnitude more objects than what you show, and yet GC cycles
> here are barely perceptible.
>
Hi,

Thank you for your reply.

So gc-elapsed is the elapsed wall-clock time.
Is there a function to obtain CPU time in Emacs Lisp?

On BSD, many years ago, I wrote a short routine that uses
resource-related system call. I am using Emacs under linux now, and I 
assume similar calls exist under linux. I checked the manual.
I will use getrusage(2), which seems to be BSD-compatible, to obtain the 
resource usage statistics and include the numbers in my post-gc-hook result.

OTOH, I have always assumed that Emacs DID eats up CPU while longish GC. 
You may recall the graphics that showed the usage of a CPU core going 
all the way to 1000 in my previous e-mail (xosview). I am attaching it 
again.
I used the graphics to show the memory usage (hand-drawn red circle) in 
my previous e-mai.

But if you look slightly above, you will notice CPU core #4 is used 100% 
(!).
That is emacs process. No other process is running that earnestly at 
that moment.
Thanks to many cores (actually I allocate 7 cores), the linux desktop 
was responding swiftly and xosview was recording system resource usage 
as the graphics shows. Only Emacs process could not respond to window 
repaint request from X when I re-arranged the windows layout, and that 
is why the Emacs window is garbled (hand-drawn blue circle was placed at 
the upper-left of the un-repainted area that remained black).

I believe Emacs indeed was eating up the CPU time in a busy loop or 
deeply nested calls. (maybe a loop that could be handled in a for loop 
with a relatively shallow stack was handled by a recursive call that can 
be nested as deep as the list length?)

Numbers from getrusage()　will give us additional insight on this matter 
hopefully.

Thank you again for all your tips.


Chiaki


PS: I found profiler-cpu-* functions, but I don't think it is wise to 
run them during GC since they seem to allocate vector tables. However, 
taking a snapshot of strack trace every now and then during GC seems 
attractive for my investigation to figure out WHERE in GC, the excessive 
time is spent.


[-- Attachment #2: emacs-hung-2.PNG --]
[-- Type: image/png, Size: 283491 bytes --]