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#39413: 26.2; Emacs gets hung Date: Mon, 16 Aug 2021 09:20:40 +0900 Message-ID: References: <85r1ynam0x.fsf@gmail.com> <44e850a0-c8dc-4aec-5706-c52db33697a1@ubin.jp> <119c5df5-080e-c45b-6498-2a2bc0f8273b@yk.rim.or.jp> <83lfme232a.fsf@gnu.org> <0b9cd846-b9f5-8351-5f45-5614bbc644c0@ubin.jp> <87sgfojjmm.fsf@gmail.com> <87fsvhwacb.fsf@gnus.org> <83wnosdwyt.fsf@gnu.org> <277eef17-0241-7245-a801-dc3707c23e5b@yk.rim.or.jp> <838s17dtpa.fsf@gnu.org> 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="20873"; mail-complaints-to="usenet@ciao.gmane.io" User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:78.0) Gecko/20100101 Thunderbird/78.13.0 Cc: chiaki.ishikawa@ubin.jp, larsi@gnus.org, 39413@debbugs.gnu.org, npostavs@gmail.com To: Eli Zaretskii Original-X-From: bug-gnu-emacs-bounces+geb-bug-gnu-emacs=m.gmane-mx.org@gnu.org Mon Aug 16 02:21:11 2021 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 1mFQNL-0005GB-57 for geb-bug-gnu-emacs@m.gmane-mx.org; Mon, 16 Aug 2021 02:21:11 +0200 Original-Received: from localhost ([::1]:41712 helo=lists1p.gnu.org) by lists.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1mFQNJ-0003Tv-0W for geb-bug-gnu-emacs@m.gmane-mx.org; Sun, 15 Aug 2021 20:21:09 -0400 Original-Received: from eggs.gnu.org ([2001:470:142:3::10]:43866) by lists.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1mFQNC-0003Tn-6H for bug-gnu-emacs@gnu.org; Sun, 15 Aug 2021 20:21:02 -0400 Original-Received: from debbugs.gnu.org ([209.51.188.43]:36426) by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.90_1) (envelope-from ) id 1mFQNB-0007vJ-V3 for bug-gnu-emacs@gnu.org; Sun, 15 Aug 2021 20:21:01 -0400 Original-Received: from Debian-debbugs by debbugs.gnu.org with local (Exim 4.84_2) (envelope-from ) id 1mFQNB-00038J-NA for bug-gnu-emacs@gnu.org; Sun, 15 Aug 2021 20:21:01 -0400 X-Loop: help-debbugs@gnu.org Resent-From: "ISHIKAWA,chiaki" Original-Sender: "Debbugs-submit" Resent-CC: bug-gnu-emacs@gnu.org Resent-Date: Mon, 16 Aug 2021 00:21:01 +0000 Resent-Message-ID: Resent-Sender: help-debbugs@gnu.org X-GNU-PR-Message: followup 39413 X-GNU-PR-Package: emacs X-GNU-PR-Keywords: unreproducible moreinfo Original-Received: via spool by 39413-submit@debbugs.gnu.org id=B39413.162907324612003 (code B ref 39413); Mon, 16 Aug 2021 00:21:01 +0000 Original-Received: (at 39413) by debbugs.gnu.org; 16 Aug 2021 00:20:46 +0000 Original-Received: from localhost ([127.0.0.1]:47972 helo=debbugs.gnu.org) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1mFQMv-00037V-Kk for submit@debbugs.gnu.org; Sun, 15 Aug 2021 20:20:46 -0400 Original-Received: from mail101.siriuscloud.jp ([219.118.72.101]:58001 helo=mail01.SiriusCloud.jp) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1mFQMt-00037M-IW for 39413@debbugs.gnu.org; Sun, 15 Aug 2021 20:20:44 -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 access01.SiriusCloud.jp (Postfix) with ESMTPA id 4GnvvX5VHzz35v5SY; Mon, 16 Aug 2021 09:20:40 +0900 (JST) Authentication-Results: access01.SiriusCloud.jp; dkim=none; dkim-atps=neutral In-Reply-To: Content-Language: en-US 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" Xref: news.gmane.io gmane.emacs.bugs:211952 Archived-At: On 2021/08/16 8:27, ISHIKAWA,chiaki wrote: > 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" >>> 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. > Aha, I realized that Emacs configure has a snipet to check for the presence of getrusage system call. Now I know there is a function in src/sysdep.c called get-internal-run-time which would be useful for my purpose except it calls make_lisp_time(make_timespec(secs, usecs * 1000)) at the end. I want to obtain precise time spent by GC by doing the following.    geturasge(RUSAGE_SELF, &usage_before_GC);    GC    geturasge(RUSAGE_SELF, &usage_after_GC); obtain the CPU time usage difference between two rusage structure to know the CPU time spent by GC. Well, get-interla-run-time is useful for obtain the AFTER-GC time, but I am not sure if we can call get-internal-run-time within the garbage-collect, at the very first line of its call due to the use of make_lisp_time. Well, I guess I have to create a function to record the CPU usage at the start of GC and then before exiting GC, calculate the difference and put it into a variable (sys time and usr time added for simplicity). I think I　will basically follow how Vgc_elapsed is updated at the latter part of garbage_collection(). I think I will return a vector of numbers from getrusage(). If you have any suggestions about how the return value/variable should look like, please let me know. If I can find a reasonably portable way to obtain cache miss and cache hit numbers of a single core process like Emacs, I may want to add it just in case. TIA. Chiaki