funcall consing

funcall consing

[Tomas Hlavaty]

Hi,

in order to optimize some elisp code, I am trying to understand where my
consing comes from.  So far it looks like that my assumption about the
cause of consing are wrong and that the cause of consing is funcall.  Is
that plausible?  I am seeing similar results like this (lexical-binding,
also byte compiled):

(benchmark-run 10 (dotimes (i 100000) (1+ i)))
;;(2.720941123 40 1.7525918699999998)
(let ((x (lambda (i) (1+ i)))) (benchmark-run 10 (dotimes (i 100000) (funcall x i))))
;;(4.9373091140000005 80 3.4835688719999958)

i.e. funcall conses a lot and introduces cca double performance penalty.

Is that right or am I doing something wrong?

Would it be possible to improve that?

Thank you in advance

Tomas

Re: funcall consing

[Eli Zaretskii]

> From: Tomas Hlavaty <tom@logand.com>
> Date: Fri, 31 Dec 2021 12:01:09 +0100
> 
> in order to optimize some elisp code, I am trying to understand where my
> consing comes from.  So far it looks like that my assumption about the
> cause of consing are wrong and that the cause of consing is funcall.  Is
> that plausible?  I am seeing similar results like this (lexical-binding,
> also byte compiled):
> 
> (benchmark-run 10 (dotimes (i 100000) (1+ i)))
> ;;(2.720941123 40 1.7525918699999998)
> (let ((x (lambda (i) (1+ i)))) (benchmark-run 10 (dotimes (i 100000) (funcall x i))))
> ;;(4.9373091140000005 80 3.4835688719999958)
> 
> i.e. funcall conses a lot and introduces cca double performance penalty.

What do you mean by "consing" in this context, and what is your
evidence for "consing" in the above example?  Is that only the
performance degradation, or is that something else?

Re: funcall consing

[LdBeth]

>>>>> In <83fsq9gdhw.fsf@gnu.org> 
>>>>>	Eli Zaretskii <eliz@gnu.org> wrote:

Tomas> (benchmark-run 10 (dotimes (i 100000) (1+ i)))
Tomas> ;;(2.720941123 40 1.7525918699999998)
Tomas> (let ((x (lambda (i) (1+ i)))) (benchmark-run 10 (dotimes (i 100000) (funcall x i))))
Tomas> ;;(4.9373091140000005 80 3.4835688719999958)

Eli> What do you mean by "consing" in this context, and what is your
Eli> evidence for "consing" in the above example?  Is that only the
Eli> performance degradation, or is that something else?

Tomas probably means this (from the docstring of benchmark-run):

Return a list of the total elapsed time for execution, the number of
garbage collections that ran, and the time taken by garbage collection.

> (4.9373091140000005 80 3.4835688719999958)

The `80' indicats the GC has been invoked 80 times. That is the direct
indication of "consing".

-- 
LDB

Re: funcall consing

[Tomas Hlavaty]

On Fri 31 Dec 2021 at 23:09, LdBeth <andpuke@foxmail.com> wrote:
> Tomas probably means this (from the docstring of benchmark-run):
>
> Return a list of the total elapsed time for execution, the number of
> garbage collections that ran, and the time taken by garbage collection.
>
>> (4.9373091140000005 80 3.4835688719999958)
>
> The `80' indicats the GC has been invoked 80 times. That is the direct
> indication of "consing".

yes, that's what I meant

Re: funcall consing

[Eli Zaretskii]

> Date: Fri, 31 Dec 2021 23:09:56 +0800
> From: LdBeth <andpuke@foxmail.com>
> Cc: Tomas Hlavaty <tom@logand.com>,
> 	emacs-devel@gnu.org
> 
> > (4.9373091140000005 80 3.4835688719999958)
> 
> The `80' indicats the GC has been invoked 80 times. That is the direct
> indication of "consing".

Why are you saying that the number of times GC has been invoked is the
direct indication of consing?  I don't think it is.  Emacs doesn't
call GC because it knows how much consing was done, it calls GC in
certain strategic points in the interpreter, when the Lisp program
happens to hit those points.  And funcall is indeed one of those
points.

Re: funcall consing

[Richard Stallman]

[[[ To any NSA and FBI agents reading my email: please consider    ]]]
[[[ whether defending the US Constitution against all enemies,     ]]]
[[[ foreign or domestic, requires you to follow Snowden's example. ]]]

  > > The `80' indicats the GC has been invoked 80 times. That is the direct
  > > indication of "consing".

  > Why are you saying that the number of times GC has been invoked is the
  > direct indication of consing?

It used to be the case, and maybe still is that the decision on
whether to call GC on any given occasion was controlled by how much
space had been allocated since the previous GC.  If that is true
nowadays, then calling GC roughly measures the amount of consing.

-- 
Dr Richard Stallman (https://stallman.org)
Chief GNUisance of the GNU Project (https://gnu.org)
Founder, Free Software Foundation (https://fsf.org)
Internet Hall-of-Famer (https://internethalloffame.org)

Re: funcall consing

[Eli Zaretskii]

> From: Richard Stallman <rms@gnu.org>
> Cc: andpuke@foxmail.com, tom@logand.com, emacs-devel@gnu.org
> Date: Fri, 31 Dec 2021 23:47:14 -0500
> 
>   > > The `80' indicats the GC has been invoked 80 times. That is the direct
>   > > indication of "consing".
> 
>   > Why are you saying that the number of times GC has been invoked is the
>   > direct indication of consing?
> 
> It used to be the case, and maybe still is that the decision on
> whether to call GC on any given occasion was controlled by how much
> space had been allocated since the previous GC.

It is still the case.  But the details matter in this case: we
actually call GC in some strategic points, regardless of how much
consing was made, and if it decides that not enough consing has
happened since the last call, it does nothing and immediately returns;
such "do-nothing" GC cycles then aren't counted in gcs-done.

> If that is true nowadays, then calling GC roughly measures the
> amount of consing.

Not necessarily.  If you write Lisp that rarely calls the functions
which call GC, then GC won't have enough opportunities to check how
much consing has happened.  This would produce fewer GC cycles,
although each cycle might collect more garbage.

Note that one of the examples posted by the OP does exactly twice GC
cycles that the other.  Which leads me to believe it had twice more
opportunities for checking how much consing was done.

So I think the caveat not to put too much faith in the _number_ of GC
cycles is still something important to keep in mind.

Re: funcall consing

[Tomas Hlavaty]

On Sat 01 Jan 2022 at 09:26, Eli Zaretskii <eliz@gnu.org> wrote:
> Note that one of the examples posted by the OP does exactly twice GC
> cycles that the other.  Which leads me to believe it had twice more
> opportunities for checking how much consing was done.
>
> So I think the caveat not to put too much faith in the _number_ of GC
> cycles is still something important to keep in mind.

In my example:

(benchmark-run 10 (dotimes (i 100000) (1+ i)))
;;(2.720941123 40 1.7525918699999998)
(let ((x (lambda (i) (1+ i)))) (benchmark-run 10 (dotimes (i 100000) (funcall x i))))
;;(4.9373091140000005 80 3.4835688719999958)

the third number is the time taken by garbage collection.  It is also
roughly doubled for the second case indicating that the second case
really generated more (say about twice as much) garbage.

Otherwise benchmark-run is not really useful for what I need.  In that
case, what is the preferred way to measure execution speed and consing?
I do not need absolute numbers, just something so that I can compare two
different implementations of the same thing and choose the better one or
focus on places to improve.

Re: funcall consing

[Eli Zaretskii]

> From: Tomas Hlavaty <tom@logand.com>
> Cc: emacs-devel@gnu.org
> Date: Sun, 02 Jan 2022 14:30:38 +0100
> 
> On Sat 01 Jan 2022 at 09:26, Eli Zaretskii <eliz@gnu.org> wrote:
> > Note that one of the examples posted by the OP does exactly twice GC
> > cycles that the other.  Which leads me to believe it had twice more
> > opportunities for checking how much consing was done.
> >
> > So I think the caveat not to put too much faith in the _number_ of GC
> > cycles is still something important to keep in mind.
> 
> In my example:
> 
> (benchmark-run 10 (dotimes (i 100000) (1+ i)))
> ;;(2.720941123 40 1.7525918699999998)
> (let ((x (lambda (i) (1+ i)))) (benchmark-run 10 (dotimes (i 100000) (funcall x i))))
> ;;(4.9373091140000005 80 3.4835688719999958)
> 
> the third number is the time taken by garbage collection.  It is also
> roughly doubled for the second case indicating that the second case
> really generated more (say about twice as much) garbage.

The longer time taken by GC doesn't necessarily mean more garbage was
collected.  Scanning the same number of Lisp objects twice the number
of times will take roughly twice the time.

> Otherwise benchmark-run is not really useful for what I need.  In that
> case, what is the preferred way to measure execution speed and consing?

My suggestion is to examine and analyze the output of garbage-collect.
There are also the various *-cells-consed variables you could use.

Re: funcall consing

[Tomas Hlavaty]

On Sun 02 Jan 2022 at 16:46, Eli Zaretskii <eliz@gnu.org> wrote:
>> Otherwise benchmark-run is not really useful for what I need.  In that
>> case, what is the preferred way to measure execution speed and consing?
>
> My suggestion is to examine and analyze the output of garbage-collect.
> There are also the various *-cells-consed variables you could use.

thank you, I'll have a look

Re: funcall consing

[Stefan Monnier]

> Otherwise benchmark-run is not really useful for what I need.  In that
> case, what is the preferred way to measure execution speed and consing?

byte-compile the code, e.g. with `benchmark-run-compiled`.

> I do not need absolute numbers, just something so that I can compare two
> different implementations of the same thing and choose the better one or
> focus on places to improve.

Presumably that code will be compiled in the end, so you want to compare
the performance of the compiled versions rather than the performance of
the interpreted versions.
The performance profile of compiled and interpreted code can be
quite different.


        Stefan

Re: funcall consing

[LdBeth]

>>>>> In <8335m8hazn.fsf@gnu.org> 
>>>>>	Eli Zaretskii <eliz@gnu.org> wrote:

ldb> The `80' indicats the GC has been invoked 80 times. That is the direct
ldb> indication of "consing".

Eli> Why are you saying that the number of times GC has been invoked is the
Eli> direct indication of consing?  I don't think it is.  Emacs doesn't
Eli> call GC because it knows how much consing was done, it calls GC in
Eli> certain strategic points in the interpreter, when the Lisp program
Eli> happens to hit those points.  And funcall is indeed one of those
Eli> points.

The docstring of `gc-cons-threshold' says:

| Number of bytes of consing between garbage collections.
| Garbage collection can happen automatically once this many bytes have been
| allocated since the last garbage collection.  All data types count.
|
| Garbage collection happens automatically only when ‘eval’ is called.

``GC checkpoints'' are not equivlent to the actually invocation of GC
that would increase `gcs-done' (that is the variable been used by
`benchmark-run' to calculate the gc numbers). Otherwise, either this
docstring is untrue or the snippet below would always print different
numbers.

```
(progn
  (print gcs-done)
  (eval '(cons 1 2))
  (print gcs-done))
```

-- 
LDB

Re: funcall consing

[Eli Zaretskii]

> Date: Sat, 01 Jan 2022 12:51:53 +0800
> From: LdBeth <andpuke@foxmail.com>
> Cc: LdBeth <andpuke@foxmail.com>,
> 	tom@logand.com,
> 	emacs-devel@gnu.org
> 
> Eli> Why are you saying that the number of times GC has been invoked is the
> Eli> direct indication of consing?  I don't think it is.  Emacs doesn't
> Eli> call GC because it knows how much consing was done, it calls GC in
> Eli> certain strategic points in the interpreter, when the Lisp program
> Eli> happens to hit those points.  And funcall is indeed one of those
> Eli> points.
> 
> The docstring of `gc-cons-threshold' says:
> 
> | Number of bytes of consing between garbage collections.
> | Garbage collection can happen automatically once this many bytes have been
> | allocated since the last garbage collection.  All data types count.
> |
> | Garbage collection happens automatically only when ‘eval’ is called.
> 
> ``GC checkpoints'' are not equivlent to the actually invocation of GC
> that would increase `gcs-done' (that is the variable been used by
> `benchmark-run' to calculate the gc numbers). Otherwise, either this
> docstring is untrue or the snippet below would always print different
> numbers.

See my other message about the details: you are reading too much into
the doc string.

Re: funcall consing

[Stefan Monnier]

Eli Zaretskii [2022-01-01 09:28:02] wrote:
> See my other message about the details: you are reading too much into
> the doc string.

Nevertheless, 80 calls to the GC suggests that Emacs has allocated more
than (* 80 gc-cons-threshold) bytes of heap data, whereas that sample
code doesn't need to allocate anything at all, at first glance (so it
should call the GC zero times).


        Stefan

Re: funcall consing

[Eli Zaretskii]

> From: Stefan Monnier <monnier@iro.umontreal.ca>
> Cc: LdBeth <andpuke@foxmail.com>,  tom@logand.com,  emacs-devel@gnu.org
> Date: Sat, 01 Jan 2022 12:05:54 -0500
> 
> Eli Zaretskii [2022-01-01 09:28:02] wrote:
> > See my other message about the details: you are reading too much into
> > the doc string.
> 
> Nevertheless, 80 calls to the GC suggests that Emacs has allocated more
> than (* 80 gc-cons-threshold) bytes of heap data, whereas that sample
> code doesn't need to allocate anything at all, at first glance (so it
> should call the GC zero times).

I wasn't really talking specifically about this case, but about a
general principle.

Re: funcall consing

[LdBeth]

>>>>> In <87ee5tm422.fsf@logand.com> 
>>>>>	Tomas Hlavaty <tom@logand.com> wrote:
Tomas> Hi,

Tomas> in order to optimize some elisp code, I am trying to understand where my
Tomas> consing comes from.  So far it looks like that my assumption about the
Tomas> cause of consing are wrong and that the cause of consing is funcall.  Is
Tomas> that plausible?  I am seeing similar results like this (lexical-binding,
Tomas> also byte compiled):

Tomas> (benchmark-run 10 (dotimes (i 100000) (1+ i)))
Tomas> ;;(2.720941123 40 1.7525918699999998)
Tomas> (let ((x (lambda (i) (1+ i)))) (benchmark-run 10 (dotimes (i 100000) (funcall x i))))
Tomas> ;;(4.9373091140000005 80 3.4835688719999958)

Tomas> i.e. funcall conses a lot and introduces cca double performance penalty.

Tomas> Is that right or am I doing something wrong?

Tomas> Would it be possible to improve that?

Try this:

```
(defun bar () (benchmark-run 10 (dotimes (i 100000) (1+ i))))
(defun foo () (let ((x (lambda (i) (1+ i))))
  (benchmark-run 10 (dotimes (i 100000) (funcall x i)))))

(byte-compile 'foo)
(byte-compile 'bar)

(foo)
(0.054734 0 0.0)
(bar)
(0.019939000000000002 0 0.0)
```

Re: funcall consing

[Tomas Hlavaty]

On Fri 31 Dec 2021 at 22:27, LdBeth <andpuke@foxmail.com> wrote:
> Try this:
>
> ```
> (defun bar () (benchmark-run 10 (dotimes (i 100000) (1+ i))))
> (defun foo () (let ((x (lambda (i) (1+ i))))
>   (benchmark-run 10 (dotimes (i 100000) (funcall x i)))))
>
> (byte-compile 'foo)
> (byte-compile 'bar)
>
> (foo)
> (0.054734 0 0.0)
> (bar)
> (0.019939000000000002 0 0.0)
> ```

amazing, thank you!