[racket] first vs car ; last vs cdr ; empty? vs null?

The GC in that first call to `vector-length` is really paying for work
related to allocating the vector.

Normally, a call to `vector-length` wouldn't present an opportunity for
the GC to fire. Combine it with `time`, though, and there are some
allocation points to set up timing. So, unfortunately, the
instrumentation to time the call to `vector-length` is what allows a GC
to happen and produce a misleading timing result.

Meanwhile, since you're running `(collect-garbage)` three times before
starting, you might not expect a GC to be needed after allocating one
big vector (that's still live). But the way the GC works, it's
essentially because a big chunk of memory has been allocated since the
last GC that can make the system perform a major GC --- particularly if
anything else at all is happening in the Racket process, such as a
sandbox-related thread.

In this case, putting a separate `(collect-garbage)` before each `time`
would probably help measure what you intended to measure.

At Sat, 8 Mar 2014 15:03:07 -0500, Greg Hendershott wrote:
> Before posting, I had repeated this multiple times, running this code
> inside a sandbox.
> 
> After seeing your reply, I tried but couldn't repro it at the command line.
> 
> I could still repro it in the sandbox. But with a fresh sandbox, now I
> can't repro it anymore. I guess some mysterious bit of state was
> causing this (but only for the first call to vector-length??).
> 
> I know the rule -- only do serious profiling at the command line. In
> this case I didn't expect it would matter. I figured "some number vs.
> some smaller number" could be due to environment overhead, but not
> "some number vs. 0". However I was wrong.
> 
> On Sat, Mar 8, 2014 at 1:57 PM, Laurent <laurent.orseau at gmail.com> wrote:
> > I get :
> >
> >> (let ((v (time (make-vector 50000000 0))))
> >     (time (vector-length v))
> >     (time (vector-length v))
> >     (time (vector-length v))
> >     (void))
> > cpu time: 188 real time: 191 gc time: 12
> >
> > cpu time: 0 real time: 0 gc time: 0
> > cpu time: 0 real time: 0 gc time: 0
> > cpu time: 0 real time: 0 gc time: 0
> >
> > Which seems consistent to me.
> >
> > Are you trying on the command line?
> >
> > Laurent
> >
> >
> > On Sat, Mar 8, 2014 at 7:35 PM, Greg Hendershott <greghendershott at gmail.com>
> > wrote:
> >>
> >> As for length:
> >>
> >> (for ([i 3]) (collect-garbage))
> >> (let ((ls (time (make-list 50000000 0))))
> >>   (time (length ls))
> >>   (time (length ls))
> >>   (time (length ls))
> >>   (void))
> >>
> >> It's what I would expect:
> >>
> >> cpu time: 6733 real time: 6744 gc time: 6419
> >> cpu time: 141 real time: 141 gc time: 0
> >> cpu time: 145 real time: 145 gc time: 0
> >> cpu time: 142 real time: 142 gc time: 0
> >>
> >> - - - - -
> >>
> >> Next, thinking about 50000000 elements made me think about vectors,
> >> vector? and vector-length.
> >>
> >> This:
> >>
> >> (for ([i 3]) (collect-garbage))
> >> (let ((v (time (make-vector 50000000 0))))
> >>   (time (vector-length v))
> >>   (time (vector-length v))
> >>   (time (vector-length v))
> >>   (void))
> >>
> >> prints:
> >>
> >> cpu time: 182 real time: 183 gc time: 1
> >> cpu time: 315 real time: 315 gc time: 314
> >> cpu time: 0 real time: 0 gc time: 0
> >> cpu time: 0 real time: 0 gc time: 0
> >>
> >> Huh?  The first call to vector-length takes even longer than making
> >> the vector (and, seems to be almost entirely gc).
> >>
> >> I would have guessed that make-vector would create a structure with
> >> the length already stored in it, and all vector-length calls would be
> >> essentially 0.
> >> ____________________
> >>   Racket Users list:
> >>   http://lists.racket-lang.org/users
> >
> >
> ____________________
>   Racket Users list:
>   http://lists.racket-lang.org/users