From mboxrd@z Thu Jan 1 00:00:00 1970 Path: news.gmane.io!.POSTED.blaine.gmane.org!not-for-mail From: Trevor Bentley Newsgroups: gmane.emacs.bugs Subject: bug#43389: 28.0.50; Emacs memory leaks using hard disk all time Date: Sat, 12 Dec 2020 12:20:57 +0100 Message-ID: <87zh2jqnhi.fsf@mail.trevorbentley.com> References: <83y2j0qb2v.fsf@gnu.org> <83o8jmu49z.fsf@gnu.org> <522e3cc0-c563-3308-7264-1b09cd5e264b@redhat.com> <87o8jltglg.fsf@mail.trevorbentley.com> <43b8f55b-d201-76e0-2d19-d97dec8798aa@redhat.com> <87im9ttfeg.fsf@mail.trevorbentley.com> <399d4681-940a-c782-b91e-750e62840cb6@redhat.com> <83pn40qkyb.fsf@gnu.org> <418751f6-41be-a5e2-908a-ea4196d5fb9b@redhat.com> <83y2inq2sp.fsf@gnu.org> <60253612-49f0-a1aa-b9e6-39cfef8d62b5@redhat.com> <83mtz3p7qy.fsf@gnu.org> <83lfenp78f.fsf@gnu.org> <83h7pbp5wh.fsf@gnu.org> <83v9dpn9em.fsf@gnu.org> <87sg8ts766.fsf@mail.trevorbentley.com> <87pn3usr13.fsf@mail.trevorbentley.com> <87eek0rmqa.fsf@mail.trevorbentley.com> <83zh2l33fv.fsf@gnu.org> Mime-Version: 1.0 Content-Type: text/plain; format=flowed Injection-Info: ciao.gmane.io; posting-host="blaine.gmane.org:116.202.254.214"; logging-data="9798"; mail-complaints-to="usenet@ciao.gmane.io" Cc: fweimer@redhat.com, 43389@debbugs.gnu.org, bugs@gnu.support, dj@redhat.com, carlos@redhat.com, michael_heerdegen@web.de, To: Stefan Monnier , Eli Zaretskii Original-X-From: bug-gnu-emacs-bounces+geb-bug-gnu-emacs=m.gmane-mx.org@gnu.org Sat Dec 12 12:23:13 2020 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 1ko2zY-0002PZ-Hk for geb-bug-gnu-emacs@m.gmane-mx.org; Sat, 12 Dec 2020 12:23:12 +0100 Original-Received: from localhost ([::1]:37086 helo=lists1p.gnu.org) by lists.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1ko2zU-00074w-AQ for geb-bug-gnu-emacs@m.gmane-mx.org; Sat, 12 Dec 2020 06:23:09 -0500 Original-Received: from eggs.gnu.org ([2001:470:142:3::10]:58974) by lists.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1ko2yQ-0006zF-MC for bug-gnu-emacs@gnu.org; Sat, 12 Dec 2020 06:22:02 -0500 Original-Received: from debbugs.gnu.org ([209.51.188.43]:60730) by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.90_1) (envelope-from ) id 1ko2yQ-0001mp-Bp for bug-gnu-emacs@gnu.org; Sat, 12 Dec 2020 06:22:02 -0500 Original-Received: from Debian-debbugs by debbugs.gnu.org with local (Exim 4.84_2) (envelope-from ) id 1ko2yQ-0000Yj-85 for bug-gnu-emacs@gnu.org; Sat, 12 Dec 2020 06:22:02 -0500 X-Loop: help-debbugs@gnu.org Resent-From: Trevor Bentley Original-Sender: "Debbugs-submit" Resent-CC: bug-gnu-emacs@gnu.org Resent-Date: Sat, 12 Dec 2020 11:22:02 +0000 Resent-Message-ID: Resent-Sender: help-debbugs@gnu.org X-GNU-PR-Message: followup 43389 X-GNU-PR-Package: emacs Original-Received: via spool by 43389-submit@debbugs.gnu.org id=B43389.16077720702041 (code B ref 43389); Sat, 12 Dec 2020 11:22:02 +0000 Original-Received: (at 43389) by debbugs.gnu.org; 12 Dec 2020 11:21:10 +0000 Original-Received: from localhost ([127.0.0.1]:44036 helo=debbugs.gnu.org) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1ko2xa-0000Wp-0N for submit@debbugs.gnu.org; Sat, 12 Dec 2020 06:21:10 -0500 Original-Received: from mail.trevorbentley.com ([37.187.5.80]:56163) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1ko2xU-0000Vv-5R for 43389@debbugs.gnu.org; Sat, 12 Dec 2020 06:21:07 -0500 Original-Received: from localhost (c188-150-0-48.bredband.comhem.se [188.150.0.48]) by mail.trevorbentley.com (Postfix) with ESMTPSA id 04E46605E7; Sat, 12 Dec 2020 12:20:57 +0100 (CET) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=mail.trevorbentley.com; s=mail; t=1607772058; bh=K1o9jufAV8cxIbI3H+yWZgDR7zgwPjeHsr2TqZkde8o=; h=From:To:Cc:Cc:Subject:In-Reply-To:References:Date:From; b=B7SIe7OoUgmgeu44IFT0yuhg1tWxYc5TI1q/QRls0XBTK/C2hFjQLs2bOMjIP56oX 3F/nOpUrSEnvpQwMJX+tpFvTc7qyJEJ2glVXVnk2gX59XclDPseVTu6mBO8tH9l8ds I22GAv9SwUFKWFwwmrbPT4K2GIU9FrO247Bbn6Gw= In-Reply-To: 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:195839 Archived-At: Stefan Monnier writes: > Do we have a `profiler-report` available for those 15 minutes? > I've taken a quick look at the massive threads in that bug > report, but haven't had the time to read in detail. AFAICT we > don't have a profiler output for those 15minutes, so it would be > good to try: > > M-x profiler-start RET RET M-x garbage-collect RET ;; > This should presumably take several minutes M-x > profiler-report RET > > and then shows us this report (using C-u RET on the top-level > elements to unfold them). I'm back with a new mtrace, a profile of the long garbage-collect, and a new discovery. First of all, the 26GB mtrace of a session that exploded to over 8GB is available in mtrace12.tar.bz2 here: https://trevorbentley.com/mtrace/ The summary log is in mtrace12_log.txt in the same directory, including output of profiler-report for only the duration of the garbage-collect, which took a record 50 minutes to complete. As you can see in the profiler log, it is, in fact, the C garbage_collect() function eating all of the time: ---- ;;(profiler-report) - ... 901307 99% Automatic GC 901281 99% + trev/slack--refresh-cache 19 0% ---- Not only that, but I added printfs in emacs itself around the garbage_collect() and gc_sweep() functions. Each line prints the unix timestamp when it began, and the 'end' lines print the duration since the start. You can see that the entire 50 minutes was spent in gc_sweep(): ---- 1607695679: garbage_collect start 1607695680: gc_sweep start 1607695680: gc_sweep end (0 s) 1607695680: garbage_collect #1085 end (1 s) 1607695761: garbage_collect start 1607695762: gc_sweep start 1607695762: gc_sweep end (0 s) 1607726912: garbage_collect start 1607726913: gc_sweep start 1607729921: gc_sweep end (3008 s) 1607729922: garbage_collect #1086 end (3010 s) ---- And finally, here's what I find very suspicious: it was nearly 9 hours since the last garbage collect ran (1607726912 - 1607695762). This is an instance that I used all day long, flittering back and forth between it and other work. It had both tons of interactive use, and tons of idle time. I don't think 9 hours between garbage collects sounds right. The last garbage collect before the long manual one also never printed an end message, which is confusing. I see no early returns in garbage_collect()... is there some macro that can trigger a return, or maybe something uses longjmp? Thanks, -Trevor