bug#17535: 24.3.91; Problems with profiling memory

bug#17535: 24.3.91; Problems with profiling memory

[Eli Zaretskii]

1. Visit profiler.el and go to this function:

    (defun profiler-cpu-profile ()
      "Return CPU profile."
      (when (profiler-running-p 'cpu)
	(profiler-make-profile
	 :type 'cpu
	 :timestamp (current-time)
	 :log (profiler-cpu-log))))

   Position cursor on "profiler-make-profile" and type "C-h f".  Emacs
   pops up a *Help* buffer saying:

     profiler-make-profile is a compiled Lisp function in `profiler.el'.

     (profiler-make-profile &key TAG VERSION TYPE LOG TIMESTAMP DIFF-P)

     This function has a compiler macro `profiler-make-profile--cmacro'.

     Not documented.

   Click on the "profiler.el" link in the *Help* buffer -- Emacs
   displays an error message saying "Unable to find location in file"

2. How to interpret the "memory profile"?  What does a line such as
   this in the profile mean:

  - execute-extended-command                                  973,272  20%

   How were the 973,272 bytes counted, and what are they 20% of?  The
   ELisp manual, where this facility is described, does not explain
   how to interpret the profiles, and neither can I find anything
   about that in the doc strings.

3. Displaying a memory profile after several minutes shows clear signs
   of overflow:

  - command-execute                                         151,652,741   0%
   - call-interactively                                     151,650,661   0%
    - dired-x-find-file                                      44,210,847   0%
     - find-file                                             44,210,847   0%
      - find-file-noselect                                   44,209,884   0%
  ...
	- normal-backup-enable-predicate                      7,091,148  -1%
	 - file-truename                                      7,091,148  -1%
	  - file-truename                                     5,910,436  -1%
	   - file-truename                                    4,729,872   1%
	    - file-truename                                   3,549,420   1%
	     - file-truename                                  2,369,208   0%
		file-truename                                 1,179,936   0%

  etc.: I see no percentage numbers except 1%, 0%, and -1%.




In GNU Emacs 24.3.91.12 (i686-pc-mingw32)
 of 2014-05-20 on HOME-C4E4A596F7
Repository revision: 117130 rgm@gnu.org-20140520154621-om1kdtav37b73we5
Windowing system distributor `Microsoft Corp.', version 5.1.2600
Configured using:
 `configure --prefix=/d/usr --enable-checking=yes,glyphs 'CFLAGS=-O0
 -gdwarf-2 -g3''

Important settings:
  value of $LANG: ENU
  locale-coding-system: cp1255

Major mode: Lisp Interaction

Minor modes in effect:
  tooltip-mode: t
  electric-indent-mode: t
  mouse-wheel-mode: t
  tool-bar-mode: t
  menu-bar-mode: t
  file-name-shadow-mode: t
  global-font-lock-mode: t
  font-lock-mode: t
  blink-cursor-mode: t
  auto-composition-mode: t
  auto-encryption-mode: t
  auto-compression-mode: t
  line-number-mode: t
  transient-mark-mode: t

Recent input:
M-x r e p o r t - e m a <tab> <return>

Recent messages:
For information about GNU Emacs and the GNU system, type C-h C-a.

Load-path shadows:
None found.

Features:
(shadow sort gnus-util mail-extr emacsbug message format-spec rfc822 mml
easymenu mml-sec mm-decode mm-bodies mm-encode mail-parse rfc2231
mailabbrev gmm-utils mailheader sendmail rfc2047 rfc2045 ietf-drums
mm-util help-fns mail-prsvr mail-utils time-date tooltip electric
uniquify ediff-hook vc-hooks lisp-float-type mwheel dos-w32 ls-lisp
w32-common-fns disp-table w32-win w32-vars tool-bar dnd fontset image
regexp-opt fringe tabulated-list newcomment lisp-mode prog-mode register
page menu-bar rfn-eshadow timer select scroll-bar mouse jit-lock
font-lock syntax facemenu font-core frame cham georgian utf-8-lang
misc-lang vietnamese tibetan thai tai-viet lao korean japanese hebrew
greek romanian slovak czech european ethiopic indian cyrillic chinese
case-table epa-hook jka-cmpr-hook help simple abbrev minibuffer nadvice
loaddefs button faces cus-face macroexp files text-properties overlay
sha1 md5 base64 format env code-pages mule custom widget
hashtable-print-readable backquote make-network-process w32notify w32
multi-tty emacs)

Memory information:
((conses 8 74014 7322)
 (symbols 32 17470 0)
 (miscs 32 33 97)
 (strings 16 10775 4534)
 (string-bytes 1 269194)
 (vectors 8 9453)
 (vector-slots 4 372707 5780)
 (floats 8 57 68)
 (intervals 28 238 94)
 (buffers 508 11))

bug#17535: 24.3.91; Problems with profiling memory

[Stefan Monnier]

>    Position cursor on "profiler-make-profile" and type "C-h f".  Emacs
>    pops up a *Help* buffer saying:
>      profiler-make-profile is a compiled Lisp function in `profiler.el'.
>      (profiler-make-profile &key TAG VERSION TYPE LOG TIMESTAMP DIFF-P)
>      This function has a compiler macro `profiler-make-profile--cmacro'.
>      Not documented.

>    Click on the "profiler.el" link in the *Help* buffer -- Emacs
>    displays an error message saying "Unable to find location in file"

Indeed.  Looks like a problem in cl-macs.el.

> 2. How to interpret the "memory profile"?  What does a line such as
>    this in the profile mean:
>   - execute-extended-command                                  973,272  20%
>    How were the 973,272 bytes counted, and what are they 20% of?  The
>    ELisp manual, where this facility is described, does not explain
>    how to interpret the profiles, and neither can I find anything
>    about that in the doc strings.

It's the number of bytes "allocated from the system" during execution of
this function.  This "allocation" is poorly defined: we don't track
allocation of individual objects but of things like cons_blocks.

>   etc.: I see no percentage numbers except 1%, 0%, and -1%.

This is just most likely a wrap-around due to too-large integers.


        Stefan

bug#17535: 24.3.91; Problems with profiling memory

[Eli Zaretskii]

> From: Stefan Monnier <monnier@iro.umontreal.ca>
> Cc: 17535@debbugs.gnu.org
> Date: Tue, 20 May 2014 15:01:34 -0400
> 
> > 2. How to interpret the "memory profile"?  What does a line such as
> >    this in the profile mean:
> >   - execute-extended-command                                  973,272  20%
> >    How were the 973,272 bytes counted, and what are they 20% of?  The
> >    ELisp manual, where this facility is described, does not explain
> >    how to interpret the profiles, and neither can I find anything
> >    about that in the doc strings.
> 
> It's the number of bytes "allocated from the system" during execution of
> this function.

But these numbers are huge.  I have hard time believing that all those
bytes were allocated in just few minutes of an almost-idle Emacs.

> This "allocation" is poorly defined: we don't track allocation of
> individual objects but of things like cons_blocks.

Do we only track allocations of Lisp objects, or just any calls to
xmalloc?

> >   etc.: I see no percentage numbers except 1%, 0%, and -1%.
> 
> This is just most likely a wrap-around due to too-large integers.

Definitely.  I thought these were already fixed, but it looks they
aren't.  I will try to take a better look.  Are there any reasons not
to do this calculation in floating-point?

bug#17535: 24.3.91; Problems with profiling memory

[Stefan Monnier]

>> > 2. How to interpret the "memory profile"?  What does a line such as
>> >    this in the profile mean:
>> >   - execute-extended-command                                  973,272  20%
>> >    How were the 973,272 bytes counted, and what are they 20% of?  The
>> >    ELisp manual, where this facility is described, does not explain
>> >    how to interpret the profiles, and neither can I find anything
>> >    about that in the doc strings.
>> It's the number of bytes "allocated from the system" during execution of
>> this function.
> But these numbers are huge.  I have hard time believing that all those
> bytes were allocated in just few minutes of an almost-idle Emacs.

It only counts allocation, so "alloc+free+alloc" counts as 2 allocs.
1MB of allocation over a few minutes of use doesn't sound particularly
odd to me.

>> This "allocation" is poorly defined: we don't track allocation of
>> individual objects but of things like cons_blocks.
> Do we only track allocations of Lisp objects, or just any calls to
> xmalloc?

Can't remember.

>> >   etc.: I see no percentage numbers except 1%, 0%, and -1%.
>> This is just most likely a wrap-around due to too-large integers.
> Definitely.  I thought these were already fixed, but it looks they
> aren't.  I will try to take a better look.  Are there any reasons not
> to do this calculation in floating-point?

The raw counts need to be integers because we can't allocate during the
sampling, but all the Elisp code could use floating point, I think.


        Stefan

bug#17535: 24.3.91; Problems with profiling memory

[Eli Zaretskii]

> From: Stefan Monnier <monnier@iro.umontreal.ca>
> Cc: 17535@debbugs.gnu.org
> Date: Tue, 20 May 2014 16:16:13 -0400
> 
> >> > 2. How to interpret the "memory profile"?  What does a line such as
> >> >    this in the profile mean:
> >> >   - execute-extended-command                                  973,272  20%
> >> >    How were the 973,272 bytes counted, and what are they 20% of?  The
> >> >    ELisp manual, where this facility is described, does not explain
> >> >    how to interpret the profiles, and neither can I find anything
> >> >    about that in the doc strings.
> >> It's the number of bytes "allocated from the system" during execution of
> >> this function.
> > But these numbers are huge.  I have hard time believing that all those
> > bytes were allocated in just few minutes of an almost-idle Emacs.
> 
> It only counts allocation, so "alloc+free+alloc" counts as 2 allocs.

Why doesn't it count a call to 'free' as a deallocation?  Ignoring
freed memory makes the memory profiler much less useful than it could
have been; e.g., it would be impossible to look for leaks if releasing
memory is ignored.  Isn't it possible to call malloc_probe with a
negative argument?

Moreover, I don't understand this part of garbage-collect:

  /* Collect profiling data.  */
  if (profiler_memory_running)
    {
      size_t swept = 0;
      size_t tot_after = total_bytes_of_live_objects ();
      if (tot_before > tot_after)
	swept = tot_before - tot_after;
      malloc_probe (swept);
    }

This looks like we count memory we just swept (i.e. released) as an
allocation.  Unless I'm missing something, that makes no sense.

> >> This "allocation" is poorly defined: we don't track allocation of
> >> individual objects but of things like cons_blocks.
> > Do we only track allocations of Lisp objects, or just any calls to
> > xmalloc?
> 
> Can't remember.

I can now answer this myself: we track all calls to xmalloc, and also
all the allocating functions, like lisp_malloc, which call malloc
directly.  IOW, we track all memory allocations except direct calls to
mmap.

> >> >   etc.: I see no percentage numbers except 1%, 0%, and -1%.
> >> This is just most likely a wrap-around due to too-large integers.
> > Definitely.  I thought these were already fixed, but it looks they
> > aren't.  I will try to take a better look.  Are there any reasons not
> > to do this calculation in floating-point?
> 
> The raw counts need to be integers because we can't allocate during the
> sampling, but all the Elisp code could use floating point, I think.

Could someone please fix this?  Without a fix, the memory profiling is
simply useless.  It's too bad we released Emacs 24.3 like that, but at
least let's fix this in 24.4.

I tried a few relatively simple tricks, but couldn't make it work,
because using floats screws the report formatting.  Which brings me to
this snippet from profiler.el:

  (defvar profiler-report-cpu-line-format
    '((50 left)
      (24 right ((19 right)
		 (5 right)))))

  (defvar profiler-report-memory-line-format
    '((55 left)
      (19 right ((14 right profiler-format-number)
		 (5 right)))))

Is it possible to have doc strings for these variables, or at least a
comment that explains this data structure, the meaning of each field,
and its possible values?  Otherwise, there's no way of adjusting them
when the report format is changed in some way.

Finally, the situation with the doc strings (the first issue I
mentioned in my original report) is worse than I thought: there are a
lot of macros in profiler.el that are defined using cl-macs.el, and
they all have the same problem: they have no doc strings, and "C-h f"
cannot find their sources, which makes reading the code unbearably
complicated.

TIA

bug#17535: 24.3.91; Problems with profiling memory

[Stefan Monnier]

>> It only counts allocation, so "alloc+free+alloc" counts as 2 allocs.
> Why doesn't it count a call to 'free' as a deallocation?

Original reason is that the memory profiler was mostly meant as a way to
get profiling with the need for a timer (using memory allocation as
a crude approximation of time).

Other reason is that deallocation largely takes place during GC and it's
unclear to which functions/backtraces to attribute the corresponding
negative (attributing them to the backtrace that happens to be current
during GC would make the numbers pretty arbitrary).

> This looks like we count memory we just swept (i.e. released) as an
> allocation.

Yes.

> Unless I'm missing something, that makes no sense.

IIRC this was motivated by the idea of using memory as a crude
approximation for time.

>   (defvar profiler-report-cpu-line-format
>     '((50 left)
>       (24 right ((19 right)
> 		 (5 right)))))
>
>   (defvar profiler-report-memory-line-format
>     '((55 left)
>       (19 right ((14 right profiler-format-number)
> 		 (5 right)))))
>
> Is it possible to have doc strings for these variables, or at least a
> comment that explains this data structure, the meaning of each field,
> and its possible values?  Otherwise, there's no way of adjusting them
> when the report format is changed in some way.

I'm not familiar with this part of the code.  Hopefully Tomohiro can help.

> mentioned in my original report) is worse than I thought: there are a
> lot of macros in profiler.el that are defined using cl-macs.el, and
> they all have the same problem: they have no doc strings, and "C-h f"
> cannot find their sources, which makes reading the code unbearably
> complicated.

That's something we need to fix in cl-macs.el, indeed.


        Stefan

bug#17535: 24.3.91; Problems with profiling memory

[Stefan Monnier]

> Original reason is that the memory profiler was mostly meant as a way to
> get profiling with the need for a timer (using memory allocation as
                ^^^^
               without
Duh!


        Stefan

bug#17535: 24.3.91; Problems with profiling memory

[Eli Zaretskii]

> From: Stefan Monnier <monnier@iro.umontreal.ca>
> Cc: Tomohiro Matsuyama <tomo@cx4a.org>,  17535@debbugs.gnu.org
> Date: Wed, 28 May 2014 14:04:34 -0400
> 
> >> It only counts allocation, so "alloc+free+alloc" counts as 2 allocs.
> > Why doesn't it count a call to 'free' as a deallocation?
> 
> Original reason is that the memory profiler was mostly meant as a way to
> get profiling with the need for a timer (using memory allocation as
> a crude approximation of time).

But since now we do have timer-based CPU profiling, we no longer need
this approximation, right?

> Other reason is that deallocation largely takes place during GC and it's
> unclear to which functions/backtraces to attribute the corresponding
> negative (attributing them to the backtrace that happens to be current
> during GC would make the numbers pretty arbitrary).

First, there are quite a few places where we allocate and deallocate
memory for things other than Lisp objects.  Normally, such memory is
deallocated right away, or very soon, after it is no longer needed.
In those cases, we should attribute the memory freeing to the current
function/backtrace.

And second, I understand the limitations caused by GC, but I think we
should still attribute memory freed during GC to GC itself.  That way,
at least at some high enough level the positive and negative probes
will balance, and the memory profile won't look like one giant leak.

If we don't count free as a negative allocation, can you envision a
situation for which the memory profile, as we have it now, would be a
useful tool?  Because I can't.

> >   (defvar profiler-report-cpu-line-format
> >     '((50 left)
> >       (24 right ((19 right)
> > 		 (5 right)))))
> >
> >   (defvar profiler-report-memory-line-format
> >     '((55 left)
> >       (19 right ((14 right profiler-format-number)
> > 		 (5 right)))))
> >
> > Is it possible to have doc strings for these variables, or at least a
> > comment that explains this data structure, the meaning of each field,
> > and its possible values?  Otherwise, there's no way of adjusting them
> > when the report format is changed in some way.
> 
> I'm not familiar with this part of the code.  Hopefully Tomohiro can help.

I hope so too.

bug#17535: 24.3.91; Problems with profiling memory

[Stefan Monnier]

> If we don't count free as a negative allocation, can you envision a
> situation for which the memory profile, as we have it now, would be a
> useful tool?  Because I can't.

Beside a crutch for timer-less situations, this was also meant to help
debug high memory use by providing a profile of where memory allocation
tends to take place.

Counting freeing as 0 would make sense in this context.

Counting freeing as negative allocation is more tricky since it goes
towards trying to track "memory use" rather than "memory allocation",
but attributing memory use to particular code locations (or backtraces)
is often somewhere between hard and meaningless.

This said, "memory profiling" is a very hard subject, and I don't think
there's an approach that will always work better than another (or maybe
there is one, but it'd have to be tremendously more complex and costly
than the simplistic profiler we have), depending on the particulars of
the bug you're tracking.  So we should probably provide both options.


        Stefan

bug#17535: 24.3.91; Problems with profiling memory

[Lars Ingebrigtsen]

Eli Zaretskii <eliz@gnu.org> writes:

> 1. Visit profiler.el and go to this function:
>
>     (defun profiler-cpu-profile ()
>       "Return CPU profile."
>       (when (profiler-running-p 'cpu)
> 	(profiler-make-profile
> 	 :type 'cpu
> 	 :timestamp (current-time)
> 	 :log (profiler-cpu-log))))
>
>    Position cursor on "profiler-make-profile" and type "C-h f".  Emacs
>    pops up a *Help* buffer saying:
>
>      profiler-make-profile is a compiled Lisp function in `profiler.el'.
>
>      (profiler-make-profile &key TAG VERSION TYPE LOG TIMESTAMP DIFF-P)
>
>      This function has a compiler macro `profiler-make-profile--cmacro'.
>
>      Not documented.
>
>    Click on the "profiler.el" link in the *Help* buffer -- Emacs
>    displays an error message saying "Unable to find location in file"

This now seems like it's fixed.

> 3. Displaying a memory profile after several minutes shows clear signs
>    of overflow:
>
>   - command-execute                                         151,652,741   0%
>    - call-interactively                                     151,650,661   0%
>     - dired-x-find-file                                      44,210,847   0%
>      - find-file                                             44,210,847   0%
>       - find-file-noselect                                   44,209,884   0%
>   ...
> 	- normal-backup-enable-predicate                      7,091,148  -1%

I'm not able to reproduce this on the current trunk.

Eli Zaretskii <eliz@gnu.org> writes:

>> Other reason is that deallocation largely takes place during GC and it's
>> unclear to which functions/backtraces to attribute the corresponding
>> negative (attributing them to the backtrace that happens to be current
>> during GC would make the numbers pretty arbitrary).
>
> First, there are quite a few places where we allocate and deallocate
> memory for things other than Lisp objects.  Normally, such memory is
> deallocated right away, or very soon, after it is no longer needed.
> In those cases, we should attribute the memory freeing to the current
> function/backtrace.
>
> And second, I understand the limitations caused by GC, but I think we
> should still attribute memory freed during GC to GC itself.  That way,
> at least at some high enough level the positive and negative probes
> will balance, and the memory profile won't look like one giant leak.
>
> If we don't count free as a negative allocation, can you envision a
> situation for which the memory profile, as we have it now, would be a
> useful tool?  Because I can't.

If we started to try to count how much was freed, too, then the numbers
would become more arbitrary?  Because GC will free things
asynchronously, etc.  Just counting the allocations sounds like a valid
thing to do to me.

But perhaps counting frees would be nice as an option?

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no

bug#17535: 24.3.91; Problems with profiling memory

[Eli Zaretskii]

> From: Lars Ingebrigtsen <larsi@gnus.org>
> Cc: 17535@debbugs.gnu.org
> Date: Sat, 05 Feb 2022 23:39:23 +0100
> 
> > 3. Displaying a memory profile after several minutes shows clear signs
> >    of overflow:
> >
> >   - command-execute                                         151,652,741   0%
> >    - call-interactively                                     151,650,661   0%
> >     - dired-x-find-file                                      44,210,847   0%
> >      - find-file                                             44,210,847   0%
> >       - find-file-noselect                                   44,209,884   0%
> >   ...
> > 	- normal-backup-enable-predicate                      7,091,148  -1%
> 
> I'm not able to reproduce this on the current trunk.

The original report was in a 32-bit build, and we now have bignums, so
if a 32-bit build doesn't reproduce that, it means bignums fixed that.

> Eli Zaretskii <eliz@gnu.org> writes:
> 
> >> Other reason is that deallocation largely takes place during GC and it's
> >> unclear to which functions/backtraces to attribute the corresponding
> >> negative (attributing them to the backtrace that happens to be current
> >> during GC would make the numbers pretty arbitrary).
> >
> > First, there are quite a few places where we allocate and deallocate
> > memory for things other than Lisp objects.  Normally, such memory is
> > deallocated right away, or very soon, after it is no longer needed.
> > In those cases, we should attribute the memory freeing to the current
> > function/backtrace.
> >
> > And second, I understand the limitations caused by GC, but I think we
> > should still attribute memory freed during GC to GC itself.  That way,
> > at least at some high enough level the positive and negative probes
> > will balance, and the memory profile won't look like one giant leak.
> >
> > If we don't count free as a negative allocation, can you envision a
> > situation for which the memory profile, as we have it now, would be a
> > useful tool?  Because I can't.
> 
> If we started to try to count how much was freed, too, then the numbers
> would become more arbitrary?  Because GC will free things
> asynchronously, etc.  Just counting the allocations sounds like a valid
> thing to do to me.
> 
> But perhaps counting frees would be nice as an option?

I have since arrived at the conclusion that the so-called "memory"
profile doesn't actually profile memory allocations, and is
more-or-less useless, especially in Emacs that has SIGPROF support
(which I guess means everywhere?).  So I think it's okay to just close
this bug report.

bug#17535: 24.3.91; Problems with profiling memory

[Lars Ingebrigtsen]

Eli Zaretskii <eliz@gnu.org> writes:

>  So I think it's okay to just close this bug report.

OK; done.

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no