Strange performance behavior

90 views
Skip to first unread message

wanp...@gmail.com

unread,
Aug 5, 2020, 11:21:08 AM8/5/20
to Racket Users
I was working on a exercism problem named Raindrops.

Problem description:
Convert a number to a string, the contents of which depend on the number's factors.

If the number has 3 as a factor, output 'Pling'.
If the number has 5 as a factor, output 'Plang'.
If the number has 7 as a factor, output 'Plong'.
If the number does not have 3, 5, or 7 as a factor, just pass the number's digits straight through.

I came out with two version.

; version 1
(define (convert n)
  (define pling (divides? 3 n))
  (define plang (divides? 5 n))
  (define plong (divides? 7 n))
  (if (or pling plang plong)
      (string-append (if pling "Pling" "")
                     (if plang "Plang" "")
                     (if plong "Plong" ""))
      (number->string n)))

; version 2
(define (convert n)
  (define table '((3 . "Pling") (5 . "Plang") (7 . "Plong")))
  (define result (for/list ([(k v) (in-dict table)] #:when (divides? k n)) v))
  (if (empty? result) (number->string n)
      (string-append* result)))

(require math/number-theory)

I thought version 1 would be faster, but it turned out to be wrong. Running with raco test got following timing information.

version 1
cpu time: 9 real time: 9 gc time: 9
version 2
cpu time: 0 real time: 0 gc time: 0

Then I ran both version in DrRacket, both output following result.
cpu time: 0 real time: 0 gc time: 0

It's strange, isn't it?

sleepnova

unread,
Aug 5, 2020, 11:34:31 AM8/5/20
to Racket Users
Sorry, forgot to attach the test suite.

wanp...@gmail.com <wanp...@gmail.com> 於 2020年8月5日 週三 下午11:21寫道:
--
You received this message because you are subscribed to a topic in the Google Groups "Racket Users" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/racket-users/LhCM51vnywg/unsubscribe.
To unsubscribe from this group and all its topics, send an email to racket-users...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/racket-users/46592171-c357-4897-af1a-bea91c838cacn%40googlegroups.com.


--
- sleepnova
呼叫小黃創辦人 & CEO
raindrops-test.rkt

Sam Tobin-Hochstadt

unread,
Aug 5, 2020, 11:44:21 AM8/5/20
to wanp...@gmail.com, Racket Users
What's happening here is that your function takes effectively 0 time,
but when you ran the first version, there was a GC pause during it
(that's why there's the "gc time: 9" there). GC pauses can happen at
any time, basically, so it's not something about what your function is
doing.

Here's a benchmark of your two functions that takes long enough to run
that it avoids some of these issues, and also runs a GC before
benchmarking: https://gist.github.com/7cb4645308d8572e2250833ef7b90b7c

On my machine, I get 40 ms for version 1, and 100 ms for version 2, as
you expected.

Sam
> --
> You received this message because you are subscribed to the Google Groups "Racket Users" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to racket-users...@googlegroups.com.

George Neuner

unread,
Aug 6, 2020, 6:35:44 AM8/6/20
to racket...@googlegroups.com
On Wed, 5 Aug 2020 08:21:07 -0700 (PDT),
"wanp...@gmail.com"
<wanp...@gmail.com> wrote:

>I was working on a exercism problem named Raindrops.
>
> :
>
>I thought version 1 would be faster, but it turned out to be wrong. Running
>with raco test got following timing information.
>
>version 1
>cpu time: 9 real time: 9 gc time: 9
>version 2
>cpu time: 0 real time: 0 gc time: 0
>
>Then I ran both version in DrRacket, both output following result.
>cpu time: 0 real time: 0 gc time: 0
>
>It's strange, isn't it?

It looks like the time for the 1st version was skewed by a garbage
collection during execution.

Generally for a decent benchmark, you need to run the code many times
and average the results. For Racket, additionally you need to
*exclude* the time for the 1st run because that will include time for
JIT compilation.

George

Joel Dueck

unread,
Aug 7, 2020, 9:23:52 AM8/7/20
to Racket Users
On Wednesday, August 5, 2020 at 10:44:21 AM UTC-5 Sam Tobin-Hochstadt wrote:
Here's a benchmark of your two functions that takes long enough to run
that it avoids some of these issues, and also runs a GC before
benchmarking: https://gist.github.com/7cb4645308d8572e2250833ef7b90b7c

What is the reason for calling `collect-garbage` twice consecutively?

Also, the docs are unclear on this, but is `(collect-garbage)` equivalent to `(collect-garbage 'major)` ?

George Neuner

unread,
Aug 8, 2020, 12:27:29 AM8/8/20
to racket...@googlegroups.com
On Fri, 7 Aug 2020 06:23:52 -0700 (PDT), "'Joel Dueck' via Racket
Users" <racket...@googlegroups.com> wrote:

>On Wednesday, August 5, 2020 at 10:44:21 AM UTC-5 Sam Tobin-Hochstadt wrote:
>
>> Here's a benchmark of your two functions that takes long enough to run
>> that it avoids some of these issues, and also runs a GC before
>> benchmarking: https://gist.github.com/7cb4645308d8572e2250833ef7b90b7c
>>
>
>What is the reason for calling `collect-garbage` twice consecutively?

It is an attempt to start with the cleanest heap possible.

Objects that have a "finalizer" get collected over 2 GC cycles - the
finalizer function gets run during the 1st collection, and then the
object memory is reclaimed during the next collection.

Running GC twice makes sure any finalized objects have been collected.


Also, when GC can run in parallel with the mutator, it is possible to
miss collecting objects that become garbage *while* GC is running.
This can't happen in BC Racket, but it might be possible in RacketCS
because Chez has a different thread model. ???


>Also, the docs are unclear on this, but is `(collect-garbage)` equivalent
>to `(collect-garbage 'major)` ?

The docs clearly state that the default is 'major.

(collect-garbage [request]) ? void?
request : (or/c 'major 'minor 'incremental) = 'major


George

Sorawee Porncharoenwase

unread,
Aug 8, 2020, 1:55:34 AM8/8/20
to George Neuner, Racket list
I even saw people doing `collect-garbage` three times, just to be safe I guess. And yet theoretically it's not guaranteed that things will be claimed back properly.

Honestly, there should be a function that does this `collect-garbage` until fixpoint or something, so that we don't need to perform this ... uh .... ritual.

--
You received this message because you are subscribed to the Google Groups "Racket Users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to racket-users...@googlegroups.com.

George Neuner

unread,
Aug 8, 2020, 3:33:12 AM8/8/20
to Sorawee Porncharoenwase, racket users

On 8/8/2020 1:55 AM, Sorawee Porncharoenwase wrote:
> I even saw people doing `collect-garbage` three times, just to be safe
> I guess. And yet theoretically it's not guaranteed that things will be
> claimed back properly.
>
> Honestly, there should be a function that does this `collect-garbage`
> until fixpoint or something, so that we don't need to perform this ...
> uh .... ritual.

There may be no documented guarantee, but I *think* the implementation
assures that 2 collections, back-to-back, are sufficient to reclaim all
objects that were garbage at the beginning of the 1st collection.  At
least for BC Racket.

And I know that sounds like weasle ... but GC efficiency is measured
statistically, and it's impossible to reclaim 100% of garbage in a
single collection without completely stopping the mutator for the
duration.  The whole point of incremental, generational  [and multispace
in general] collection is to avoid long pauses.

George

Matthew Flatt

unread,
Aug 8, 2020, 9:45:54 AM8/8/20
to George Neuner, Sorawee Porncharoenwase, racket users
At Sat, 8 Aug 2020 03:32:57 -0400, George Neuner wrote:
>
> On 8/8/2020 1:55 AM, Sorawee Porncharoenwase wrote:
> > I even saw people doing `collect-garbage` three times, just to be safe
> > I guess. And yet theoretically it's not guaranteed that things will be
> > claimed back properly.
> >
> > Honestly, there should be a function that does this `collect-garbage`
> > until fixpoint or something, so that we don't need to perform this ...
> > uh .... ritual.
>
> There may be no documented guarantee, but I *think* the implementation
> assures that 2 collections, back-to-back, are sufficient to reclaim all
> objects that were garbage at the beginning of the 1st collection.  At
> least for BC Racket.

In the absence of finalization, then a single `collect-garbage` would
always be sufficient, and a second `collect-garage` would have no
effect.

For the specific benchmark in this thread as run in plain `racket`, I
think a single `collect-garbage` is sufficient, and that's what I
normally do.

But finalization complicates the picture --- especially finalization
via `register-finalizer`, since the finalizers run in a background
thread. Because of that background thread, in a context that uses a
library like `racket/gui`, I sometimes use repetitions of

(collect-garbage)
(sync (system-idle-evt))

It's difficult to know whether the libraries that you use rely on
finalization. Also, finalization means that there is no simple number
of `(collect-garbage)`s and `(sync (system-idle-evt))`s that are needed
to really collect everything that could potentially be collected;
finalization chains can require an arbitrary number of
`(collect-garbage)` cycles to clean up (so libraries should avoid
finalization chains!). The collector is precise and the compiler is
safe-for-space, so you can reason about the reachability of an
individual value, but reasoning precisely about overall memory use
across many libraries is difficult or impossible.

Using an extra `(collect-garbage)` is not ideal and often not
necessary, but it's a reasonable just-to-be-sure habit.


Matthew

George Neuner

unread,
Aug 8, 2020, 11:14:50 AM8/8/20
to Matthew Flatt, racket users
Yes.  But, at least if you use the generational collector, you know that
once an object has been finalized it will be collected the next time the
GC looks at it:  i.e. at or before the next major collection.

But there is the issue of incremental GC.  Incremental complicates the
notion of the GC "cycle" because it interleaves GC with execution of the
mutator and splits a single "full" collection into many partial
collections.  I don't know enough about Racket's implementation to say
whether objects that become garbage *during* a GC cycle can be collected
in that same cycle, or whether they must wait for the next.


But in truth these details should not matter much except for debugging,
benchmarking, or for programs that must operate in limited memory.


> It's difficult to know whether the libraries that you use rely on
> finalization. Also, finalization means that there is no simple number
> of `(collect-garbage)`s and `(sync (system-idle-evt))`s that are needed
> to really collect everything that could potentially be collected;
> finalization chains can require an arbitrary number of
> `(collect-garbage)` cycles to clean up (so libraries should avoid
> finalization chains!). The collector is precise and the compiler is
> safe-for-space, so you can reason about the reachability of an
> individual value, but reasoning precisely about overall memory use
> across many libraries is difficult or impossible.
>
> Using an extra `(collect-garbage)` is not ideal and often not
> necessary, but it's a reasonable just-to-be-sure habit.
>
>
> Matthew

George

wanp...@gmail.com

unread,
Aug 9, 2020, 1:20:32 AM8/9/20
to Racket Users
Thanks, that make sense!

One more thing which bothers me is if I put a (collect-garbage) in front of the testing, I got gc time: 0 if not I got gc time: 9.
Why can't 1 gc reclaim all memory during execution while it can before executes?

Sam Tobin-Hochstadt 在 2020年8月5日 星期三下午11:44:21 [UTC+8] 的信中寫道:

George Neuner

unread,
Aug 9, 2020, 1:35:21 AM8/9/20
to wanp...@gmail.com, racket users

On 8/9/2020 1:20 AM, wanp...@gmail.com wrote:
>
> One more thing which bothers me is if I put a (collect-garbage) in
> front of the testing, I got gc time: 0 if not I got gc time: 9.
> Why can't 1 gc reclaim all memory during execution while it can before
> executes?

Those numbers show *time* spent working, not what was done.  If you
collect before running your program, at that point little has been
allocated, and little or nothing has been freed, and so the GC has
little to do ... hence it spends '0' time doing it  [zero meaning below
the resolution of the computer's clock].  Once your program starts
running, memory is being allocated and freed, and so a GC in the middle
or at the end has much more work to do.

George


sleepnova

unread,
Aug 9, 2020, 9:42:55 AM8/9/20
to racket users
Oh, I got it. Thank you for the explanation!

George Neuner <gneu...@comcast.net> 於 2020年8月9日 週日 下午1:35寫道:
Reply all
Reply to author
Forward
0 new messages