GNU bug report logs - #43389
28.0.50; Emacs memory leaks

Previous Next

Full log

View this message in rfc822 format

From: Trevor Bentley <trevor <at> trevorbentley.com>
To: Stefan Monnier <monnier <at> iro.umontreal.ca>, Eli Zaretskii <eliz <at> gnu.org>
Cc: fweimer <at> redhat.com, 43389 <at> debbugs.gnu.org, bugs <at> gnu.support, dj <at> redhat.com, carlos <at> redhat.com, michael_heerdegen <at> web.de, 
Subject: bug#43389: 28.0.50; Emacs memory leaks using hard disk all time
Date: Sat, 12 Dec 2020 12:20:57 +0100

Stefan Monnier <monnier <at> iro.umontreal.ca> 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

Previous Next

GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.