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.ors...@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 <greghendersh...@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 ____________________ Racket Users list: http://lists.racket-lang.org/users
