bug#43389: 28.0.50; Emacs memory leaks

[Russell Adams <RLAdams@AdamsInfoServ.Com>]

On Thu, Sep 17, 2020 at 10:47:04PM +0200, Russell Adams wrote:
> From Emacs memory-usage package:
>
> Garbage collection stats:
> ((conses 16 1912248 251798) (symbols 48 54872 19) (strings 32 327552 81803) (string-bytes 1 12344346) (vectors 16 158994) (vector-slots 8 2973919 339416) (floats 8 992 4604) (intervals 56 182607 7492) (buffers 1000 195))
>
>  =>	29.2MB (+ 3.84MB dead) in conses
> 	2.51MB (+ 0.89kB dead) in symbols
> 	10.00MB (+ 2.50MB dead) in strings
> 	11.8MB in string-bytes
> 	2.43MB in vectors
> 	22.7MB (+ 2.59MB dead) in vector-slots
> 	7.75kB (+ 36.0kB dead) in floats
> 	9.75MB (+  410kB dead) in intervals
> 	 190kB in buffers
>
> Total in lisp objects: 97.9MB (live 88.5MB, dead 9.36MB)

I had the memory leak occur again and this time I had the
glibc-malloc-trace-utils loaded and running from the start.

So my emacs grew to 8GB in RAM, and what was curious is if it was a
background task (not window focused on an emacsclient), then the
memory stayed the same. When I had the window focused, I could watch
the memory constantly increasing in htop a few megs at a time.

Garbage collection stats:
((conses 16 1749077 1176908)
 (symbols 48 47530 38)
 (strings 32 307123 144020)
 (string-bytes 1 10062511)
 (vectors 16 113172)
 (vector-slots 8 2105205 486800)
 (floats 8 709 1719)
 (intervals 56 174593 44804)
 (buffers 1000 71))

 =>	26.7MB (+ 18.0MB dead) in conses
	2.18MB (+ 1.78kB dead) in symbols
	9.37MB (+ 4.40MB dead) in strings
	9.60MB in string-bytes
	1.73MB in vectors
	16.1MB (+ 3.71MB dead) in vector-slots
	5.54kB (+ 13.4kB dead) in floats
	9.32MB (+ 2.39MB dead) in intervals
	69.3kB in buffers

Total in lisp objects:  103MB (live 75.0MB, dead 28.5MB)

Buffer ralloc memory usage:
47 buffers
3.36MB total ( 232kB in gaps)
      Size	Gap	Name

    926626	1504	AIS.org
    690050	1933	Personal.org
    553850	2000	Abuffer.org
    490398	3851	*Packages*
    215653	2000	KB.org
     76686	1708	X230.org
     59841	2123	Agenda.org
     51375	51076	*sly-events for sbcl*
     51060	1902	ASC.org
     44596	2000	Contacts.org
     36825	1792	*Messages*
     23882	2309	*org-caldav-debug*
     22867	2000	rgb.lisp
     14678	746	*sly-mrepl for sbcl*
      6640	1173	VirtualFCMap.lisp
      4096	2000	 *code-converting-work*
      3409	16717	 *http orgmode.org:443*
      1946	104	*Org Agenda*
      1528	2028	 *http gaming.demosthenes.org*-491231
      1524	2028	 *http gaming.demosthenes.org*-15349
      1518	2028	 *http gaming.demosthenes.org*
      1276	1368	*sly-inferior-lisp for sbcl*
      1231	2026	 *http gaming.demosthenes.org*-464306
      1208	825	*Help*
       679	1574	*Buffer Details*
       641	1975	 *Agenda Commands*
       531	1494	*Calendar*
       324	2008	 *http melpa.org:443*
       278	3775	*helm M-x*
       185	1838	*org caldav sync result*
       144	2000	*scratch*
        57	21434	*helm find files*
        44	5610	 *icalendar-work*
        30	2000	 *sly-fontify*
        21	2000	*log-edit-files*
        20	0	 *pdf-info-query--escape*
        18	4077	*helm mini*
        12	8630	 *code-conversion-work*
         5	4065	 *Echo Area 1*
         0	2033	 *Minibuf-1*
         0	20	 *Minibuf-0*
         0	20	 *server*
         0	4060	 *Echo Area 0*
         0	61547	 *sly-1*
         0	20	 *sly-dds-1-1*
         0	20	*changes to ~/ASC/Software/Snaps/*
         0	20	*vc*

I started emacs with:

MTRACE_CTL_FILE=mtraceEMACS.mtr LD_PRELOAD=~/software/glibc-malloc-trace-utils/libmtrace.so ~/.local/bin/emacs --daemon >> ~/.config/emacs/emacs.log 2>&1

This created some huge files. By the time I reached 8GB in RAM, the
mtr file for the main process (I think) was 53 GB. I also have little mtrace
files littered everywhere in different project directories.

-rw-r--r--   1 adamsrl adamsrl  53G Nov 26 13:23 mtraceEMACS.mtr.15236
-rw-r--r--   1 adamsrl adamsrl 4.2G Nov 26 13:36 my.wl
-rw-r--r--   1 adamsrl adamsrl 1.3G Nov 26 13:50 mtraceEMACS.mtr.15236.allocs
-rw-r--r--   1 adamsrl adamsrl  32K Nov 26 13:55 mtraceEMACS.mtr.15236.binnedallocs.log
-rw-r--r--   1 adamsrl adamsrl 6.0G Nov 26 15:12 vmrssout
-rw-r--r--   1 adamsrl adamsrl 6.0G Nov 26 15:12 vmout
-rw-r--r--   1 adamsrl adamsrl 8.6G Nov 26 15:12 idealrssout

I converted the mtraceEMACS.mtr.15236 to my.wl using trace2wl.

The trace_run command did this output:

% ~/software/glibc-malloc-trace-utils/trace_run ./my.wl vmout vmrssout idealrssout
11,757,635,230,744 cycles
4,532,472,554 usec wall time
5,966,752,470 usec across 3 threads
8,461,721,600 bytes Max RSS (218,308,608 -> 8,680,030,208)
Starting VmRSS 218308608 (bytes)
Starting VmSize 219549696 (bytes)
Starting MaxRSS 218308608 (bytes)
Ending VmRSS 8680030208 (bytes)
Ending VmSize 8903626752 (bytes)
Ending MaxRSS 8680030208 (bytes)
8,131,008 Kb Max Ideal RSS

sizeof ticks_t is 8
Avg malloc time:    145 in 422,186,832 calls
Avg calloc time: 12,538 in  1,164,584 calls
Avg realloc time:   566 in  3,294,165 calls
Avg free time:      110 in 449,397,629 calls
Total call time: 127,318,389,383 cycles

These files are impossible to share around, is there anything I can
run to extract anything else useful from them?

% ~/software/glibc-malloc-trace-utils/trace_statistics mtraceEMACS.mtr.15236
Min allocation size: 0
Max allocation size: 1603869
Mean allocation size: 128

I did follow the instructions for downsampling, but I haven't a clue
what to do in Octave. Is it worth posting those files?

I have the impression this is more about how often more RAM was
requested, and not the source of the call?

I should mention I'm present in #emacs and happy to discuss there.

------------------------------------------------------------------
Russell Adams                            RLAdams@AdamsInfoServ.com

PGP Key ID:     0x1160DCB3           http://www.adamsinfoserv.com/

Fingerprint:    1723 D8CA 4280 1EC9 557F  66E8 1154 E018 1160 DCB3