Re: High run time variance

[Luca Saiu <positron@gnu.org>]

[-- Attachment #1: Type: text/plain, Size: 9708 bytes --]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Hello Ludovic.

Ludovic Courtès wrote:
> Hi Luca,
> 
> Luca Saiu <positron@gnu.org> writes:
> 
>> (define (fibo n)
>>   (if (< n 2)
>>       n
>>       (+ (fibo (- n 1))
>>          (fibo (- n 2)))))
> 
> This function is not tail-recursive, so it consumes stack space, which
> increases the amount of memory the GC has to scan. My guess is that
> this has to do with the time spent in GC.

Well, no.  That's easy to prove with Boehm's GC, by setting
GC_PRINT_STATS=1. The log is quite big, so I'm attaching it separately
as fibo-with-GC_PRINT_STATS.  Anyway the result is that there is no
collection while computing fibo (I'm speaking about 1.9 using the VM),
which is to be expected: Bohem's GC can only trigger a collection at
allocation time.
  q-fibo.scm is the file which I had called q.scm in my first report,
with n = 35.

We can also completely disable the GC by setting GC_DONT_GC, and the
effect is still there:
[luca@optimum ~/tmp]$ export GC_DONT_GC=1; unset GC_PRINT_STATS; rm -rf
~/.cache/guile/; for i in `seq 10`; do time guile --autocompile
q-fibo.scm; echo; done
;;; note: autocompilation is enabled, set GUILE_AUTO_COMPILE=0
;;;       or pass the --no-autocompile argument to disable.
;;; compiling q-fibo.scm
;;; compiled
/home/luca/.cache/guile/ccache/2.0-0.P-LE-8/home/luca/tmp/q-fibo.scm.go
(begin (fibo n)) returned 9227465 in 2.79 seconds.
(begin (fibo n)) returned 9227465 in 2.79 seconds.
(begin (fibo n)) returned 9227465 in 2.78 seconds.

real	0m8.429s
user	0m8.420s
sys	0m0.020s

(begin (fibo n)) returned 9227465 in 2.59 seconds.
(begin (fibo n)) returned 9227465 in 2.59 seconds.
(begin (fibo n)) returned 9227465 in 2.6 seconds.

real	0m7.792s
user	0m7.800s
sys	0m0.010s

(begin (fibo n)) returned 9227465 in 2.95 seconds.
(begin (fibo n)) returned 9227465 in 2.93 seconds.
(begin (fibo n)) returned 9227465 in 2.94 seconds.

real	0m8.829s
user	0m8.820s
sys	0m0.010s

(begin (fibo n)) returned 9227465 in 2.64 seconds.
(begin (fibo n)) returned 9227465 in 2.64 seconds.
(begin (fibo n)) returned 9227465 in 2.65 seconds.

real	0m7.949s
user	0m7.940s
sys	0m0.000s

(begin (fibo n)) returned 9227465 in 2.73 seconds.
(begin (fibo n)) returned 9227465 in 2.74 seconds.
(begin (fibo n)) returned 9227465 in 2.73 seconds.

real	0m8.216s
user	0m8.190s
sys	0m0.000s

(begin (fibo n)) returned 9227465 in 2.6 seconds.
(begin (fibo n)) returned 9227465 in 2.61 seconds.
(begin (fibo n)) returned 9227465 in 2.61 seconds.

real	0m7.835s
user	0m7.820s
sys	0m0.020s

(begin (fibo n)) returned 9227465 in 2.97 seconds.
(begin (fibo n)) returned 9227465 in 2.97 seconds.
(begin (fibo n)) returned 9227465 in 2.98 seconds.

real	0m8.933s
user	0m8.910s
sys	0m0.000s

(begin (fibo n)) returned 9227465 in 2.61 seconds.
(begin (fibo n)) returned 9227465 in 2.6 seconds.
(begin (fibo n)) returned 9227465 in 2.61 seconds.

real	0m7.826s
user	0m7.810s
sys	0m0.010s

(begin (fibo n)) returned 9227465 in 2.92 seconds.
(begin (fibo n)) returned 9227465 in 2.93 seconds.
(begin (fibo n)) returned 9227465 in 2.92 seconds.

real	0m8.789s
user	0m8.780s
sys	0m0.000s

(begin (fibo n)) returned 9227465 in 2.55 seconds.
(begin (fibo n)) returned 9227465 in 2.55 seconds.
(begin (fibo n)) returned 9227465 in 2.55 seconds.

real	0m7.671s
user	0m7.670s
sys	0m0.000s

> Could you try with a tail-recursive version?

Well, of course I've used a different function :-). Here's the source
q-f.scm:
==================================================================
(define-macro (benchmark . body)
  ;; Yes, I know that this is ugly and non-hygienic.  That's
  ;; not the problem.
  `(let* ((t0 (array-ref (times) 0))
          (result (begin ,@body))
          (t1 (array-ref (times) 0)))
     (format #t
             "~a returned ~a in ~a seconds.\n"
             '(begin ,@body)
             result
             (/ (- t1 t0) 100.0))
     result))

(define-macro (thrice . body)
  `(begin
     ,@body
     ,@body
     ,@body))

(define (f n)
  (if (zero? n)
      0
      (f (- n 1))))

(define n 100000000)
(thrice (benchmark (f n)))
==================================================================

So, the result:
[luca@optimum ~/tmp]$ unset GC_DONT_GC; unset GC_PRINT_STATS; rm -rf
~/.cache/guile/; for i in `seq 10`; do time guile --autocompile q-f.scm;
echo; done
;;; note: autocompilation is enabled, set GUILE_AUTO_COMPILE=0
;;;       or pass the --no-autocompile argument to disable.
;;; compiling q-f.scm
;;; compiled
/home/luca/.cache/guile/ccache/2.0-0.P-LE-8/home/luca/tmp/q-f.scm.go
(begin (f n)) returned 0 in 5.19 seconds.
(begin (f n)) returned 0 in 5.19 seconds.
(begin (f n)) returned 0 in 5.18 seconds.

real	0m15.641s
user	0m15.640s
sys	0m0.010s

(begin (f n)) returned 0 in 5.21 seconds.
(begin (f n)) returned 0 in 5.2 seconds.
(begin (f n)) returned 0 in 5.2 seconds.

real	0m15.631s
user	0m15.620s
sys	0m0.000s

(begin (f n)) returned 0 in 5.18 seconds.
(begin (f n)) returned 0 in 5.18 seconds.
(begin (f n)) returned 0 in 5.18 seconds.

real	0m15.554s
user	0m15.540s
sys	0m0.020s

(begin (f n)) returned 0 in 5.2 seconds.
(begin (f n)) returned 0 in 5.21 seconds.
(begin (f n)) returned 0 in 5.2 seconds.

real	0m15.621s
user	0m15.630s
sys	0m0.000s

(begin (f n)) returned 0 in 5.05 seconds.
(begin (f n)) returned 0 in 5.05 seconds.
(begin (f n)) returned 0 in 5.05 seconds.

real	0m15.173s
user	0m15.180s
sys	0m0.010s

(begin (f n)) returned 0 in 5.18 seconds.
(begin (f n)) returned 0 in 5.17 seconds.
(begin (f n)) returned 0 in 5.18 seconds.

real	0m15.550s
user	0m15.550s
sys	0m0.010s

(begin (f n)) returned 0 in 5.24 seconds.
(begin (f n)) returned 0 in 5.24 seconds.
(begin (f n)) returned 0 in 5.24 seconds.

real	0m15.744s
user	0m15.750s
sys	0m0.000s

(begin (f n)) returned 0 in 5.25 seconds.
(begin (f n)) returned 0 in 5.25 seconds.
(begin (f n)) returned 0 in 5.24 seconds.

real	0m15.773s
user	0m15.770s
sys	0m0.010s

(begin (f n)) returned 0 in 5.2 seconds.
(begin (f n)) returned 0 in 5.2 seconds.
(begin (f n)) returned 0 in 5.2 seconds.

real	0m15.626s
user	0m15.630s
sys	0m0.010s

(begin (f n)) returned 0 in 5.26 seconds.
(begin (f n)) returned 0 in 5.26 seconds.
(begin (f n)) returned 0 in 5.26 seconds.

real	0m15.793s
user	0m15.800s
sys	0m0.010s

And with a bigger n, n = 1000000000:

[luca@optimum ~/tmp]$ unset GC_DONT_GC; unset GC_PRINT_STATS; rm -rf
~/.cache/guile/; for i in `seq 10`; do time guile --autocompile
q-f-big-n.scm; echo; done
;;; note: autocompilation is enabled, set GUILE_AUTO_COMPILE=0
;;;       or pass the --no-autocompile argument to disable.
;;; compiling q-f-big-n.scm
;;; compiled
/home/luca/.cache/guile/ccache/2.0-0.P-LE-8/home/luca/tmp/q-f-big-n.scm.go
(begin (f n)) returned 0 in 51.79 seconds.
(begin (f n)) returned 0 in 51.77 seconds.
(begin (f n)) returned 0 in 51.77 seconds.

real	2m35.411s
user	2m35.380s
sys	0m0.050s

(begin (f n)) returned 0 in 52.34 seconds.
(begin (f n)) returned 0 in 52.34 seconds.
(begin (f n)) returned 0 in 52.35 seconds.

real	2m37.051s
user	2m37.020s
sys	0m0.030s

(begin (f n)) returned 0 in 51.97 seconds.
(begin (f n)) returned 0 in 51.97 seconds.
(begin (f n)) returned 0 in 51.98 seconds.

real	2m35.949s
user	2m35.930s
sys	0m0.010s

(begin (f n)) returned 0 in 52.55 seconds.
(begin (f n)) returned 0 in 52.54 seconds.
(begin (f n)) returned 0 in 52.54 seconds.

real	2m37.651s
user	2m37.610s
sys	0m0.040s

(begin (f n)) returned 0 in 52.02 seconds.
(begin (f n)) returned 0 in 52.03 seconds.
(begin (f n)) returned 0 in 52.01 seconds.

real	2m36.084s
user	2m36.060s
sys	0m0.040s

(begin (f n)) returned 0 in 51.78 seconds.
(begin (f n)) returned 0 in 51.79 seconds.
(begin (f n)) returned 0 in 51.79 seconds.

real	2m35.382s
user	2m35.310s
sys	0m0.060s

(begin (f n)) returned 0 in 51.39 seconds.
(begin (f n)) returned 0 in 51.39 seconds.
(begin (f n)) returned 0 in 51.39 seconds.

real	2m34.191s
user	2m34.150s
sys	0m0.040s

(begin (f n)) returned 0 in 52.25 seconds.
(begin (f n)) returned 0 in 52.25 seconds.
(begin (f n)) returned 0 in 52.25 seconds.

real	2m36.763s
user	2m36.730s
sys	0m0.040s

(begin (f n)) returned 0 in 52.0 seconds.
(begin (f n)) returned 0 in 51.99 seconds.
(begin (f n)) returned 0 in 52.01 seconds.

real	2m36.014s
user	2m35.960s
sys	0m0.050s

(begin (f n)) returned 0 in 49.9 seconds.
(begin (f n)) returned 0 in 49.9 seconds.
(begin (f n)) returned 0 in 49.89 seconds.

real	2m29.714s
user	2m29.660s
sys	0m0.030s

The effect is much weaker in either case, when using tail-recursive
functions. This is interesting.
  Can the problem be related to the alignment of the Guile stack? It's
not related to the collector, but it may well be about stack access.

Has Guile been tested recently on architectures such as Sparc, requiring
aligned access? If it works reliably on Sparc, could the issue still be
about alignment, but with respect to cache lines?
  Notice that this last program should be very cache-friendly.

> Thanks,

Thank you,

- --
Luca Saiu
http://www-lipn.univ-paris13.fr/~saiu
GNU epsilon: http://www.gnu.org/software/epsilon
Marionnet:   http://www.marionnet.org
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.10 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org

iEYEARECAAYFAkux7/wACgkQvzOavibF0obEAgCePe61GGtoB24RNFkdM0bankXp
o+4AniFih5wvlnXSP5erZXX3csWCs5u/
=6CMC
-----END PGP SIGNATURE-----

[-- Attachment #2: fibo-with-GC_PRINT_STATS --]
[-- Type: text/plain, Size: 45706 bytes --]

[luca@optimum ~/tmp]$ unset GC_DONT_GC; export GC_PRINT_STATS=1; rm -rf ~/.cache/guile/; for i in `seq 10`; do time guile --autocompile q-fibo.scm; echo; done
Increasing heap size by 65536 after 0 allocated bytes
Number of processors = 8, number of marker threads = 8
Started 7 mark helper threads
Initiating full world-stop collection!

--> Marking for collection 1 after 0 allocated bytes
Collection 0 reclaimed 0 bytes ---> heapsize = 65536 bytes
World-stopped marking took 0 msecs (0 in average)
Heap contains 0 pointer-containing + 0 pointer-free reachable bytes
0 finalization table entries; 0 disappearing links alive
0 objects are eligible for immediate finalization; 0 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Increasing heap size by 65536 after 0 allocated bytes
Adding block map for size of 32 granules (512 bytes)
Adding block map for size of 84 granules (1344 bytes)
Adding block map for size of 0 granules (0 bytes)
Adding block map for size of 3 granules (48 bytes)
Adding block map for size of 2 granules (32 bytes)
Adding block map for size of 1 granules (16 bytes)
Adding block map for size of 17 granules (272 bytes)
Adding block map for size of 5 granules (80 bytes)
Adding block map for size of 4 granules (64 bytes)
Grew fo table to 1 entries
Increasing heap size by 65536 after 99536 allocated bytes
Initiating full world-stop collection!

--> Marking for collection 2 after 103648 allocated bytes
Collection 1 reclaimed 0 bytes ---> heapsize = 196608 bytes
World-stopped marking took 0 msecs (0 in average)
Heap contains 84368 pointer-containing + 14320 pointer-free reachable bytes
1 finalization table entries; 0 disappearing links alive
0 objects are eligible for immediate finalization; 0 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Grew dl table to 1 entries
Adding block map for size of 7 granules (112 bytes)
Adding block map for size of 13 granules (208 bytes)
Adding block map for size of 20 granules (320 bytes)
Grew dl table to 2 entries
Grew dl table to 4 entries
Grew dl table to 8 entries
Adding block map for size of 12 granules (192 bytes)
Adding block map for size of 8 granules (128 bytes)
Grew dl table to 16 entries
Increasing heap size by 69632 after 30592 allocated bytes
Adding block map for size of 42 granules (672 bytes)
Increasing heap size by 90112 after 101760 allocated bytes
Increasing heap size by 122880 after 183248 allocated bytes
Adding block map for size of 9 granules (144 bytes)
Increasing heap size by 684032 after 204432 allocated bytes
Adding block map for size of 15 granules (240 bytes)
Adding block map for size of 16 granules (256 bytes)
Grew dl table to 32 entries
Grew fo table to 2 entries
Grew fo table to 4 entries
Adding block map for size of 18 granules (288 bytes)
Adding block map for size of 6 granules (96 bytes)
Adding block map for size of 11 granules (176 bytes)
Adding block map for size of 10 granules (160 bytes)
Initiating full world-stop collection!

--> Marking for collection 3 after 968688 allocated bytes
Collection 2 reclaimed 4896 bytes ---> heapsize = 1163264 bytes
World-stopped marking took 10 msecs (3 in average)
Heap contains 893184 pointer-containing + 63328 pointer-free reachable bytes
4 finalization table entries; 25 disappearing links alive
0 objects are eligible for immediate finalization; 1 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 10 msecs
Increasing heap size by 389120 after 53168 allocated bytes
Increasing heap size by 520192 after 510544 allocated bytes
Initiating full world-stop collection!

--> Marking for collection 4 after 1033968 allocated bytes
Collection 3 reclaimed 77936 bytes ---> heapsize = 2072576 bytes
World-stopped marking took 0 msecs (2 in average)
Heap contains 1258864 pointer-containing + 152928 pointer-free reachable bytes
4 finalization table entries; 26 disappearing links alive
0 objects are eligible for immediate finalization; 0 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Increasing heap size by 716800 after 119232 allocated bytes
Grew dl table to 64 entries
Adding block map for size of 128 granules (2048 bytes)
;;; note: autocompilation is enabled, set GUILE_AUTO_COMPILE=0
;;;       or pass the --no-autocompile argument to disable.
;;; compiling q-fibo.scm
Initiating full world-stop collection!

--> Marking for collection 5 after 1219392 allocated bytes
Collection 4 reclaimed 567168 bytes ---> heapsize = 2789376 bytes
World-stopped marking took 0 msecs (2 in average)
Heap contains 1862960 pointer-containing + 217904 pointer-free reachable bytes
5 finalization table entries; 55 disappearing links alive
0 objects are eligible for immediate finalization; 0 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Increasing heap size by 933888 after 284352 allocated bytes
Initiating full world-stop collection!

--> Marking for collection 6 after 1490640 allocated bytes
Collection 5 reclaimed 560224 bytes ---> heapsize = 3723264 bytes
World-stopped marking took 0 msecs (1 in average)
Heap contains 2507120 pointer-containing + 319120 pointer-free reachable bytes
5 finalization table entries; 65 disappearing links alive
0 objects are eligible for immediate finalization; 0 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Increasing heap size by 1249280 after 3824 allocated bytes
Grew dl table to 128 entries
Grew fo table to 8 entries
Adding block map for size of 23 granules (368 bytes)
Adding block map for size of 50 granules (800 bytes)
Initiating full world-stop collection!

--> Marking for collection 7 after 1963888 allocated bytes
Collection 6 reclaimed 773792 bytes ---> heapsize = 4972544 bytes
World-stopped marking took 10 msecs (2 in average)
Heap contains 3368416 pointer-containing + 412384 pointer-free reachable bytes
7 finalization table entries; 129 disappearing links alive
0 objects are eligible for immediate finalization; 0 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 10 msecs
Adding block map for size of 19 granules (304 bytes)
Grew dl table to 256 entries
Increasing heap size by 1658880 after 372640 allocated bytes
Adding block map for size of 14 granules (224 bytes)
Initiating full world-stop collection!

--> Marking for collection 8 after 2613952 allocated bytes
Collection 7 reclaimed 997088 bytes ---> heapsize = 6631424 bytes
World-stopped marking took 10 msecs (3 in average)
Heap contains 4372400 pointer-containing + 560176 pointer-free reachable bytes
7 finalization table entries; 145 disappearing links alive
0 objects are eligible for immediate finalization; 43 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 10 msecs
Increasing heap size by 2211840 after 238064 allocated bytes
;;; compiled /home/luca/.cache/guile/ccache/2.0-0.P-LE-8/home/luca/tmp/q-fibo.scm.go
(begin (fibo n)) returned 9227465 in 2.56 seconds.
(begin (fibo n)) returned 9227465 in 2.56 seconds.
(begin (fibo n)) returned 9227465 in 2.56 seconds.

real	0m7.768s
user	0m7.760s
sys	0m0.000s

Increasing heap size by 65536 after 0 allocated bytes
Number of processors = 8, number of marker threads = 8
Started 7 mark helper threads
Initiating full world-stop collection!

--> Marking for collection 1 after 0 allocated bytes
Collection 0 reclaimed 0 bytes ---> heapsize = 65536 bytes
World-stopped marking took 0 msecs (0 in average)
Heap contains 0 pointer-containing + 0 pointer-free reachable bytes
0 finalization table entries; 0 disappearing links alive
0 objects are eligible for immediate finalization; 0 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Increasing heap size by 65536 after 0 allocated bytes
Adding block map for size of 32 granules (512 bytes)
Adding block map for size of 84 granules (1344 bytes)
Adding block map for size of 0 granules (0 bytes)
Adding block map for size of 3 granules (48 bytes)
Adding block map for size of 2 granules (32 bytes)
Adding block map for size of 1 granules (16 bytes)
Adding block map for size of 17 granules (272 bytes)
Adding block map for size of 5 granules (80 bytes)
Adding block map for size of 4 granules (64 bytes)
Grew fo table to 1 entries
Increasing heap size by 65536 after 99536 allocated bytes
Initiating full world-stop collection!

--> Marking for collection 2 after 103648 allocated bytes
Collection 1 reclaimed 0 bytes ---> heapsize = 196608 bytes
World-stopped marking took 0 msecs (0 in average)
Heap contains 83664 pointer-containing + 14320 pointer-free reachable bytes
1 finalization table entries; 0 disappearing links alive
0 objects are eligible for immediate finalization; 0 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Grew dl table to 1 entries
Adding block map for size of 7 granules (112 bytes)
Adding block map for size of 13 granules (208 bytes)
Adding block map for size of 20 granules (320 bytes)
Grew dl table to 2 entries
Grew dl table to 4 entries
Grew dl table to 8 entries
Adding block map for size of 12 granules (192 bytes)
Adding block map for size of 8 granules (128 bytes)
Grew dl table to 16 entries
Increasing heap size by 69632 after 30592 allocated bytes
Adding block map for size of 42 granules (672 bytes)
Increasing heap size by 90112 after 101760 allocated bytes
Increasing heap size by 122880 after 187344 allocated bytes
Adding block map for size of 9 granules (144 bytes)
Increasing heap size by 684032 after 204432 allocated bytes
Adding block map for size of 15 granules (240 bytes)
Adding block map for size of 16 granules (256 bytes)
Grew dl table to 32 entries
Grew fo table to 2 entries
Grew fo table to 4 entries
Adding block map for size of 18 granules (288 bytes)
Adding block map for size of 6 granules (96 bytes)
Adding block map for size of 11 granules (176 bytes)
Adding block map for size of 10 granules (160 bytes)
Initiating full world-stop collection!

--> Marking for collection 3 after 976880 allocated bytes
Collection 2 reclaimed 4896 bytes ---> heapsize = 1163264 bytes
World-stopped marking took 10 msecs (3 in average)
Heap contains 895712 pointer-containing + 60880 pointer-free reachable bytes
4 finalization table entries; 25 disappearing links alive
0 objects are eligible for immediate finalization; 1 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 10 msecs
Increasing heap size by 389120 after 67712 allocated bytes
Increasing heap size by 520192 after 515360 allocated bytes
Initiating full world-stop collection!

--> Marking for collection 4 after 1038672 allocated bytes
Collection 3 reclaimed 78560 bytes ---> heapsize = 2072576 bytes
World-stopped marking took 0 msecs (2 in average)
Heap contains 1259264 pointer-containing + 151552 pointer-free reachable bytes
4 finalization table entries; 26 disappearing links alive
0 objects are eligible for immediate finalization; 0 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Increasing heap size by 716800 after 101792 allocated bytes
Grew dl table to 64 entries
Adding block map for size of 128 granules (2048 bytes)
(begin (fibo n)) returned 9227465 in 2.83 seconds.
(begin (fibo n)) returned 9227465 in 2.83 seconds.
(begin (fibo n)) returned 9227465 in 2.83 seconds.

real	0m8.515s
user	0m8.510s
sys	0m0.000s

Increasing heap size by 65536 after 0 allocated bytes
Number of processors = 8, number of marker threads = 8
Started 7 mark helper threads
Initiating full world-stop collection!

--> Marking for collection 1 after 0 allocated bytes
Collection 0 reclaimed 0 bytes ---> heapsize = 65536 bytes
World-stopped marking took 10 msecs (10 in average)
Heap contains 0 pointer-containing + 0 pointer-free reachable bytes
0 finalization table entries; 0 disappearing links alive
0 objects are eligible for immediate finalization; 0 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 10 msecs
Increasing heap size by 65536 after 0 allocated bytes
Adding block map for size of 32 granules (512 bytes)
Adding block map for size of 84 granules (1344 bytes)
Adding block map for size of 0 granules (0 bytes)
Adding block map for size of 3 granules (48 bytes)
Adding block map for size of 2 granules (32 bytes)
Adding block map for size of 1 granules (16 bytes)
Adding block map for size of 17 granules (272 bytes)
Adding block map for size of 5 granules (80 bytes)
Adding block map for size of 4 granules (64 bytes)
Grew fo table to 1 entries
Increasing heap size by 65536 after 99536 allocated bytes
Initiating full world-stop collection!

--> Marking for collection 2 after 103648 allocated bytes
Collection 1 reclaimed 0 bytes ---> heapsize = 196608 bytes
World-stopped marking took 0 msecs (5 in average)
Heap contains 84352 pointer-containing + 14320 pointer-free reachable bytes
1 finalization table entries; 0 disappearing links alive
0 objects are eligible for immediate finalization; 0 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Grew dl table to 1 entries
Adding block map for size of 7 granules (112 bytes)
Adding block map for size of 13 granules (208 bytes)
Adding block map for size of 20 granules (320 bytes)
Grew dl table to 2 entries
Grew dl table to 4 entries
Grew dl table to 8 entries
Adding block map for size of 12 granules (192 bytes)
Adding block map for size of 8 granules (128 bytes)
Grew dl table to 16 entries
Increasing heap size by 69632 after 30592 allocated bytes
Adding block map for size of 42 granules (672 bytes)
Increasing heap size by 90112 after 101760 allocated bytes
Increasing heap size by 122880 after 187344 allocated bytes
Adding block map for size of 9 granules (144 bytes)
Increasing heap size by 684032 after 204432 allocated bytes
Adding block map for size of 15 granules (240 bytes)
Adding block map for size of 16 granules (256 bytes)
Grew dl table to 32 entries
Grew fo table to 2 entries
Grew fo table to 4 entries
Adding block map for size of 18 granules (288 bytes)
Adding block map for size of 6 granules (96 bytes)
Adding block map for size of 11 granules (176 bytes)
Adding block map for size of 10 granules (160 bytes)
Initiating full world-stop collection!

--> Marking for collection 3 after 976880 allocated bytes
Collection 2 reclaimed 4896 bytes ---> heapsize = 1163264 bytes
World-stopped marking took 0 msecs (3 in average)
Heap contains 894272 pointer-containing + 60464 pointer-free reachable bytes
4 finalization table entries; 25 disappearing links alive
0 objects are eligible for immediate finalization; 1 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Increasing heap size by 389120 after 72240 allocated bytes
Increasing heap size by 520192 after 515792 allocated bytes
Initiating full world-stop collection!

--> Marking for collection 4 after 1039104 allocated bytes
Collection 3 reclaimed 78992 bytes ---> heapsize = 2072576 bytes
World-stopped marking took 0 msecs (2 in average)
Heap contains 1259184 pointer-containing + 150992 pointer-free reachable bytes
4 finalization table entries; 26 disappearing links alive
0 objects are eligible for immediate finalization; 0 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Increasing heap size by 716800 after 104928 allocated bytes
Grew dl table to 64 entries
Adding block map for size of 128 granules (2048 bytes)
(begin (fibo n)) returned 9227465 in 2.93 seconds.
(begin (fibo n)) returned 9227465 in 2.94 seconds.
(begin (fibo n)) returned 9227465 in 2.93 seconds.

real	0m8.822s
user	0m8.820s
sys	0m0.030s

Increasing heap size by 65536 after 0 allocated bytes
Number of processors = 8, number of marker threads = 8
Started 7 mark helper threads
Initiating full world-stop collection!

--> Marking for collection 1 after 0 allocated bytes
Collection 0 reclaimed 0 bytes ---> heapsize = 65536 bytes
World-stopped marking took 0 msecs (0 in average)
Heap contains 0 pointer-containing + 0 pointer-free reachable bytes
0 finalization table entries; 0 disappearing links alive
0 objects are eligible for immediate finalization; 0 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Increasing heap size by 65536 after 0 allocated bytes
Adding block map for size of 32 granules (512 bytes)
Adding block map for size of 84 granules (1344 bytes)
Adding block map for size of 0 granules (0 bytes)
Adding block map for size of 3 granules (48 bytes)
Adding block map for size of 2 granules (32 bytes)
Adding block map for size of 1 granules (16 bytes)
Adding block map for size of 17 granules (272 bytes)
Adding block map for size of 5 granules (80 bytes)
Adding block map for size of 4 granules (64 bytes)
Grew fo table to 1 entries
Increasing heap size by 65536 after 95440 allocated bytes
Initiating full world-stop collection!

--> Marking for collection 2 after 103648 allocated bytes
Collection 1 reclaimed 0 bytes ---> heapsize = 196608 bytes
World-stopped marking took 0 msecs (0 in average)
Heap contains 84352 pointer-containing + 18416 pointer-free reachable bytes
1 finalization table entries; 0 disappearing links alive
0 objects are eligible for immediate finalization; 0 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Grew dl table to 1 entries
Adding block map for size of 7 granules (112 bytes)
Adding block map for size of 13 granules (208 bytes)
Adding block map for size of 20 granules (320 bytes)
Grew dl table to 2 entries
Grew dl table to 4 entries
Grew dl table to 8 entries
Adding block map for size of 12 granules (192 bytes)
Increasing heap size by 69632 after 30000 allocated bytes
Adding block map for size of 8 granules (128 bytes)
Grew dl table to 16 entries
Adding block map for size of 42 granules (672 bytes)
Increasing heap size by 90112 after 101760 allocated bytes
Increasing heap size by 122880 after 187344 allocated bytes
Adding block map for size of 9 granules (144 bytes)
Increasing heap size by 684032 after 204432 allocated bytes
Adding block map for size of 15 granules (240 bytes)
Adding block map for size of 16 granules (256 bytes)
Grew dl table to 32 entries
Grew fo table to 2 entries
Grew fo table to 4 entries
Adding block map for size of 18 granules (288 bytes)
Adding block map for size of 6 granules (96 bytes)
Adding block map for size of 11 granules (176 bytes)
Adding block map for size of 10 granules (160 bytes)
Initiating full world-stop collection!

--> Marking for collection 3 after 976880 allocated bytes
Collection 2 reclaimed 4896 bytes ---> heapsize = 1163264 bytes
World-stopped marking took 0 msecs (0 in average)
Heap contains 895840 pointer-containing + 65024 pointer-free reachable bytes
4 finalization table entries; 25 disappearing links alive
0 objects are eligible for immediate finalization; 1 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Increasing heap size by 389120 after 72240 allocated bytes
Increasing heap size by 520192 after 515792 allocated bytes
Initiating full world-stop collection!

--> Marking for collection 4 after 1039104 allocated bytes
Collection 3 reclaimed 74896 bytes ---> heapsize = 2072576 bytes
World-stopped marking took 10 msecs (2 in average)
Heap contains 1261952 pointer-containing + 155664 pointer-free reachable bytes
4 finalization table entries; 26 disappearing links alive
0 objects are eligible for immediate finalization; 0 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 10 msecs
Increasing heap size by 716800 after 106656 allocated bytes
Grew dl table to 64 entries
Adding block map for size of 128 granules (2048 bytes)
(begin (fibo n)) returned 9227465 in 2.81 seconds.
(begin (fibo n)) returned 9227465 in 2.8 seconds.
(begin (fibo n)) returned 9227465 in 2.8 seconds.

real	0m8.426s
user	0m8.420s
sys	0m0.000s

Increasing heap size by 65536 after 0 allocated bytes
Number of processors = 8, number of marker threads = 8
Started 7 mark helper threads
Initiating full world-stop collection!

--> Marking for collection 1 after 0 allocated bytes
Collection 0 reclaimed 0 bytes ---> heapsize = 65536 bytes
World-stopped marking took 0 msecs (0 in average)
Heap contains 0 pointer-containing + 0 pointer-free reachable bytes
0 finalization table entries; 0 disappearing links alive
0 objects are eligible for immediate finalization; 0 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Increasing heap size by 65536 after 0 allocated bytes
Adding block map for size of 32 granules (512 bytes)
Adding block map for size of 84 granules (1344 bytes)
Adding block map for size of 0 granules (0 bytes)
Adding block map for size of 3 granules (48 bytes)
Adding block map for size of 2 granules (32 bytes)
Adding block map for size of 1 granules (16 bytes)
Adding block map for size of 17 granules (272 bytes)
Adding block map for size of 5 granules (80 bytes)
Adding block map for size of 4 granules (64 bytes)
Grew fo table to 1 entries
Increasing heap size by 65536 after 99536 allocated bytes
Initiating full world-stop collection!

--> Marking for collection 2 after 103648 allocated bytes
Collection 1 reclaimed 0 bytes ---> heapsize = 196608 bytes
World-stopped marking took 0 msecs (0 in average)
Heap contains 84368 pointer-containing + 14320 pointer-free reachable bytes
1 finalization table entries; 0 disappearing links alive
0 objects are eligible for immediate finalization; 0 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Grew dl table to 1 entries
Adding block map for size of 7 granules (112 bytes)
Adding block map for size of 13 granules (208 bytes)
Adding block map for size of 20 granules (320 bytes)
Grew dl table to 2 entries
Grew dl table to 4 entries
Grew dl table to 8 entries
Adding block map for size of 12 granules (192 bytes)
Adding block map for size of 8 granules (128 bytes)
Grew dl table to 16 entries
Increasing heap size by 69632 after 30528 allocated bytes
Adding block map for size of 42 granules (672 bytes)
Increasing heap size by 90112 after 105840 allocated bytes
Increasing heap size by 122880 after 191376 allocated bytes
Adding block map for size of 9 granules (144 bytes)
Increasing heap size by 684032 after 204368 allocated bytes
Adding block map for size of 15 granules (240 bytes)
Adding block map for size of 16 granules (256 bytes)
Grew dl table to 32 entries
Grew fo table to 2 entries
Grew fo table to 4 entries
Adding block map for size of 18 granules (288 bytes)
Adding block map for size of 6 granules (96 bytes)
Adding block map for size of 11 granules (176 bytes)
Adding block map for size of 10 granules (160 bytes)
Initiating full world-stop collection!

--> Marking for collection 3 after 980912 allocated bytes
Collection 2 reclaimed 4896 bytes ---> heapsize = 1163264 bytes
World-stopped marking took 0 msecs (0 in average)
Heap contains 893760 pointer-containing + 64640 pointer-free reachable bytes
4 finalization table entries; 25 disappearing links alive
0 objects are eligible for immediate finalization; 1 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Increasing heap size by 389120 after 64608 allocated bytes
Increasing heap size by 520192 after 511872 allocated bytes
Initiating full world-stop collection!

--> Marking for collection 4 after 1035184 allocated bytes
Collection 3 reclaimed 75008 bytes ---> heapsize = 2072576 bytes
World-stopped marking took 0 msecs (0 in average)
Heap contains 1259024 pointer-containing + 151056 pointer-free reachable bytes
4 finalization table entries; 26 disappearing links alive
0 objects are eligible for immediate finalization; 0 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Increasing heap size by 716800 after 102496 allocated bytes
Grew dl table to 64 entries
Adding block map for size of 128 granules (2048 bytes)
(begin (fibo n)) returned 9227465 in 2.79 seconds.
(begin (fibo n)) returned 9227465 in 2.8 seconds.
(begin (fibo n)) returned 9227465 in 2.79 seconds.

real	0m8.400s
user	0m8.380s
sys	0m0.010s

Increasing heap size by 65536 after 0 allocated bytes
Number of processors = 8, number of marker threads = 8
Started 7 mark helper threads
Initiating full world-stop collection!

--> Marking for collection 1 after 0 allocated bytes
Collection 0 reclaimed 0 bytes ---> heapsize = 65536 bytes
World-stopped marking took 10 msecs (10 in average)
Heap contains 0 pointer-containing + 0 pointer-free reachable bytes
0 finalization table entries; 0 disappearing links alive
0 objects are eligible for immediate finalization; 0 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 10 msecs
Increasing heap size by 65536 after 0 allocated bytes
Adding block map for size of 32 granules (512 bytes)
Adding block map for size of 84 granules (1344 bytes)
Adding block map for size of 0 granules (0 bytes)
Adding block map for size of 3 granules (48 bytes)
Adding block map for size of 2 granules (32 bytes)
Adding block map for size of 1 granules (16 bytes)
Adding block map for size of 17 granules (272 bytes)
Adding block map for size of 5 granules (80 bytes)
Adding block map for size of 4 granules (64 bytes)
Grew fo table to 1 entries
Increasing heap size by 65536 after 99536 allocated bytes
Initiating full world-stop collection!

--> Marking for collection 2 after 103648 allocated bytes
Collection 1 reclaimed 0 bytes ---> heapsize = 196608 bytes
World-stopped marking took 0 msecs (5 in average)
Heap contains 84368 pointer-containing + 14320 pointer-free reachable bytes
1 finalization table entries; 0 disappearing links alive
0 objects are eligible for immediate finalization; 0 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Grew dl table to 1 entries
Adding block map for size of 7 granules (112 bytes)
Adding block map for size of 13 granules (208 bytes)
Adding block map for size of 20 granules (320 bytes)
Grew dl table to 2 entries
Grew dl table to 4 entries
Grew dl table to 8 entries
Adding block map for size of 12 granules (192 bytes)
Adding block map for size of 8 granules (128 bytes)
Grew dl table to 16 entries
Increasing heap size by 69632 after 30592 allocated bytes
Adding block map for size of 42 granules (672 bytes)
Increasing heap size by 90112 after 101760 allocated bytes
Increasing heap size by 122880 after 187344 allocated bytes
Adding block map for size of 9 granules (144 bytes)
Increasing heap size by 684032 after 204432 allocated bytes
Adding block map for size of 15 granules (240 bytes)
Adding block map for size of 16 granules (256 bytes)
Grew dl table to 32 entries
Grew fo table to 2 entries
Grew fo table to 4 entries
Adding block map for size of 18 granules (288 bytes)
Adding block map for size of 6 granules (96 bytes)
Adding block map for size of 11 granules (176 bytes)
Adding block map for size of 10 granules (160 bytes)
Initiating full world-stop collection!

--> Marking for collection 3 after 976880 allocated bytes
Collection 2 reclaimed 4896 bytes ---> heapsize = 1163264 bytes
World-stopped marking took 0 msecs (3 in average)
Heap contains 894208 pointer-containing + 60720 pointer-free reachable bytes
4 finalization table entries; 25 disappearing links alive
0 objects are eligible for immediate finalization; 1 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Increasing heap size by 389120 after 67712 allocated bytes
Increasing heap size by 520192 after 515360 allocated bytes
Initiating full world-stop collection!

--> Marking for collection 4 after 1034576 allocated bytes
Collection 3 reclaimed 78560 bytes ---> heapsize = 2072576 bytes
World-stopped marking took 10 msecs (5 in average)
Heap contains 1262528 pointer-containing + 149568 pointer-free reachable bytes
4 finalization table entries; 26 disappearing links alive
0 objects are eligible for immediate finalization; 0 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 10 msecs
Increasing heap size by 716800 after 108688 allocated bytes
Grew dl table to 64 entries
Adding block map for size of 128 granules (2048 bytes)
(begin (fibo n)) returned 9227465 in 2.95 seconds.
(begin (fibo n)) returned 9227465 in 2.95 seconds.
(begin (fibo n)) returned 9227465 in 2.95 seconds.

real	0m8.872s
user	0m8.870s
sys	0m0.010s

Increasing heap size by 65536 after 0 allocated bytes
Number of processors = 8, number of marker threads = 8
Started 7 mark helper threads
Initiating full world-stop collection!

--> Marking for collection 1 after 0 allocated bytes
Collection 0 reclaimed 0 bytes ---> heapsize = 65536 bytes
World-stopped marking took 0 msecs (0 in average)
Heap contains 0 pointer-containing + 0 pointer-free reachable bytes
0 finalization table entries; 0 disappearing links alive
0 objects are eligible for immediate finalization; 0 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Increasing heap size by 65536 after 0 allocated bytes
Adding block map for size of 32 granules (512 bytes)
Adding block map for size of 84 granules (1344 bytes)
Adding block map for size of 0 granules (0 bytes)
Adding block map for size of 3 granules (48 bytes)
Adding block map for size of 2 granules (32 bytes)
Adding block map for size of 1 granules (16 bytes)
Adding block map for size of 17 granules (272 bytes)
Adding block map for size of 5 granules (80 bytes)
Adding block map for size of 4 granules (64 bytes)
Grew fo table to 1 entries
Increasing heap size by 65536 after 99536 allocated bytes
Initiating full world-stop collection!

--> Marking for collection 2 after 103648 allocated bytes
Collection 1 reclaimed 0 bytes ---> heapsize = 196608 bytes
World-stopped marking took 0 msecs (0 in average)
Heap contains 84224 pointer-containing + 14320 pointer-free reachable bytes
1 finalization table entries; 0 disappearing links alive
0 objects are eligible for immediate finalization; 0 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Grew dl table to 1 entries
Adding block map for size of 7 granules (112 bytes)
Adding block map for size of 13 granules (208 bytes)
Adding block map for size of 20 granules (320 bytes)
Grew dl table to 2 entries
Grew dl table to 4 entries
Grew dl table to 8 entries
Adding block map for size of 12 granules (192 bytes)
Adding block map for size of 8 granules (128 bytes)
Grew dl table to 16 entries
Increasing heap size by 69632 after 30592 allocated bytes
Adding block map for size of 42 granules (672 bytes)
Increasing heap size by 90112 after 97664 allocated bytes
Increasing heap size by 122880 after 183248 allocated bytes
Adding block map for size of 9 granules (144 bytes)
Increasing heap size by 684032 after 204432 allocated bytes
Adding block map for size of 15 granules (240 bytes)
Adding block map for size of 16 granules (256 bytes)
Grew dl table to 32 entries
Grew fo table to 2 entries
Grew fo table to 4 entries
Adding block map for size of 18 granules (288 bytes)
Adding block map for size of 6 granules (96 bytes)
Adding block map for size of 11 granules (176 bytes)
Adding block map for size of 10 granules (160 bytes)
Initiating full world-stop collection!

--> Marking for collection 3 after 972784 allocated bytes
Collection 2 reclaimed 4896 bytes ---> heapsize = 1163264 bytes
World-stopped marking took 0 msecs (0 in average)
Heap contains 891536 pointer-containing + 62512 pointer-free reachable bytes
4 finalization table entries; 25 disappearing links alive
0 objects are eligible for immediate finalization; 1 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Increasing heap size by 389120 after 72656 allocated bytes
Increasing heap size by 520192 after 511760 allocated bytes
Initiating full world-stop collection!

--> Marking for collection 4 after 1035184 allocated bytes
Collection 3 reclaimed 79152 bytes ---> heapsize = 2072576 bytes
World-stopped marking took 10 msecs (2 in average)
Heap contains 1256544 pointer-containing + 152320 pointer-free reachable bytes
4 finalization table entries; 26 disappearing links alive
0 objects are eligible for immediate finalization; 0 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 10 msecs
Increasing heap size by 716800 after 108448 allocated bytes
Grew dl table to 64 entries
Adding block map for size of 128 granules (2048 bytes)
(begin (fibo n)) returned 9227465 in 3.27 seconds.
(begin (fibo n)) returned 9227465 in 3.26 seconds.
(begin (fibo n)) returned 9227465 in 3.27 seconds.

real	0m9.811s
user	0m9.800s
sys	0m0.010s

Increasing heap size by 65536 after 0 allocated bytes
Number of processors = 8, number of marker threads = 8
Started 7 mark helper threads
Initiating full world-stop collection!

--> Marking for collection 1 after 0 allocated bytes
Collection 0 reclaimed 0 bytes ---> heapsize = 65536 bytes
World-stopped marking took 0 msecs (0 in average)
Heap contains 0 pointer-containing + 0 pointer-free reachable bytes
0 finalization table entries; 0 disappearing links alive
0 objects are eligible for immediate finalization; 0 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Increasing heap size by 65536 after 0 allocated bytes
Adding block map for size of 32 granules (512 bytes)
Adding block map for size of 84 granules (1344 bytes)
Adding block map for size of 0 granules (0 bytes)
Adding block map for size of 3 granules (48 bytes)
Adding block map for size of 2 granules (32 bytes)
Adding block map for size of 1 granules (16 bytes)
Adding block map for size of 17 granules (272 bytes)
Adding block map for size of 5 granules (80 bytes)
Adding block map for size of 4 granules (64 bytes)
Grew fo table to 1 entries
Increasing heap size by 65536 after 99536 allocated bytes
Initiating full world-stop collection!

--> Marking for collection 2 after 103648 allocated bytes
Collection 1 reclaimed 0 bytes ---> heapsize = 196608 bytes
World-stopped marking took 0 msecs (0 in average)
Heap contains 84368 pointer-containing + 14320 pointer-free reachable bytes
1 finalization table entries; 0 disappearing links alive
0 objects are eligible for immediate finalization; 0 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Grew dl table to 1 entries
Adding block map for size of 7 granules (112 bytes)
Adding block map for size of 13 granules (208 bytes)
Adding block map for size of 20 granules (320 bytes)
Grew dl table to 2 entries
Grew dl table to 4 entries
Grew dl table to 8 entries
Adding block map for size of 12 granules (192 bytes)
Adding block map for size of 8 granules (128 bytes)
Grew dl table to 16 entries
Increasing heap size by 69632 after 30592 allocated bytes
Adding block map for size of 42 granules (672 bytes)
Increasing heap size by 90112 after 101760 allocated bytes
Increasing heap size by 122880 after 187344 allocated bytes
Adding block map for size of 9 granules (144 bytes)
Increasing heap size by 684032 after 204432 allocated bytes
Adding block map for size of 15 granules (240 bytes)
Adding block map for size of 16 granules (256 bytes)
Grew dl table to 32 entries
Grew fo table to 2 entries
Grew fo table to 4 entries
Adding block map for size of 18 granules (288 bytes)
Adding block map for size of 6 granules (96 bytes)
Adding block map for size of 11 granules (176 bytes)
Adding block map for size of 10 granules (160 bytes)
Initiating full world-stop collection!

--> Marking for collection 3 after 976880 allocated bytes
Collection 2 reclaimed 4896 bytes ---> heapsize = 1163264 bytes
World-stopped marking took 0 msecs (0 in average)
Heap contains 894448 pointer-containing + 60496 pointer-free reachable bytes
4 finalization table entries; 25 disappearing links alive
0 objects are eligible for immediate finalization; 1 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Increasing heap size by 389120 after 72240 allocated bytes
Increasing heap size by 520192 after 515792 allocated bytes
Initiating full world-stop collection!

--> Marking for collection 4 after 1039104 allocated bytes
Collection 3 reclaimed 78992 bytes ---> heapsize = 2072576 bytes
World-stopped marking took 10 msecs (2 in average)
Heap contains 1260272 pointer-containing + 151632 pointer-free reachable bytes
4 finalization table entries; 26 disappearing links alive
0 objects are eligible for immediate finalization; 0 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 10 msecs
Increasing heap size by 716800 after 107392 allocated bytes
Grew dl table to 64 entries
Adding block map for size of 128 granules (2048 bytes)
(begin (fibo n)) returned 9227465 in 3.0 seconds.
(begin (fibo n)) returned 9227465 in 3.01 seconds.
(begin (fibo n)) returned 9227465 in 3.0 seconds.

real	0m9.026s
user	0m9.020s
sys	0m0.010s

Increasing heap size by 65536 after 0 allocated bytes
Number of processors = 8, number of marker threads = 8
Started 7 mark helper threads
Initiating full world-stop collection!

--> Marking for collection 1 after 0 allocated bytes
Collection 0 reclaimed 0 bytes ---> heapsize = 65536 bytes
World-stopped marking took 0 msecs (0 in average)
Heap contains 0 pointer-containing + 0 pointer-free reachable bytes
0 finalization table entries; 0 disappearing links alive
0 objects are eligible for immediate finalization; 0 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Increasing heap size by 65536 after 0 allocated bytes
Adding block map for size of 32 granules (512 bytes)
Adding block map for size of 84 granules (1344 bytes)
Adding block map for size of 0 granules (0 bytes)
Adding block map for size of 3 granules (48 bytes)
Adding block map for size of 2 granules (32 bytes)
Adding block map for size of 1 granules (16 bytes)
Adding block map for size of 17 granules (272 bytes)
Adding block map for size of 5 granules (80 bytes)
Adding block map for size of 4 granules (64 bytes)
Grew fo table to 1 entries
Increasing heap size by 65536 after 99536 allocated bytes
Initiating full world-stop collection!

--> Marking for collection 2 after 103648 allocated bytes
Collection 1 reclaimed 0 bytes ---> heapsize = 196608 bytes
World-stopped marking took 0 msecs (0 in average)
Heap contains 84240 pointer-containing + 14320 pointer-free reachable bytes
1 finalization table entries; 0 disappearing links alive
0 objects are eligible for immediate finalization; 0 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Grew dl table to 1 entries
Adding block map for size of 7 granules (112 bytes)
Adding block map for size of 13 granules (208 bytes)
Adding block map for size of 20 granules (320 bytes)
Grew dl table to 2 entries
Grew dl table to 4 entries
Grew dl table to 8 entries
Adding block map for size of 12 granules (192 bytes)
Adding block map for size of 8 granules (128 bytes)
Grew dl table to 16 entries
Increasing heap size by 69632 after 30592 allocated bytes
Adding block map for size of 42 granules (672 bytes)
Increasing heap size by 90112 after 101760 allocated bytes
Increasing heap size by 122880 after 187344 allocated bytes
Adding block map for size of 9 granules (144 bytes)
Increasing heap size by 684032 after 204432 allocated bytes
Adding block map for size of 15 granules (240 bytes)
Adding block map for size of 16 granules (256 bytes)
Grew dl table to 32 entries
Grew fo table to 2 entries
Grew fo table to 4 entries
Adding block map for size of 18 granules (288 bytes)
Adding block map for size of 6 granules (96 bytes)
Adding block map for size of 11 granules (176 bytes)
Adding block map for size of 10 granules (160 bytes)
Initiating full world-stop collection!

--> Marking for collection 3 after 976880 allocated bytes
Collection 2 reclaimed 4896 bytes ---> heapsize = 1163264 bytes
World-stopped marking took 0 msecs (0 in average)
Heap contains 892864 pointer-containing + 60400 pointer-free reachable bytes
4 finalization table entries; 25 disappearing links alive
0 objects are eligible for immediate finalization; 1 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Increasing heap size by 389120 after 72240 allocated bytes
Increasing heap size by 520192 after 511600 allocated bytes
Initiating full world-stop collection!

--> Marking for collection 4 after 1035008 allocated bytes
Collection 3 reclaimed 78992 bytes ---> heapsize = 2072576 bytes
World-stopped marking took 0 msecs (0 in average)
Heap contains 1262336 pointer-containing + 149040 pointer-free reachable bytes
4 finalization table entries; 26 disappearing links alive
0 objects are eligible for immediate finalization; 0 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Increasing heap size by 716800 after 112480 allocated bytes
Grew dl table to 64 entries
Adding block map for size of 128 granules (2048 bytes)
(begin (fibo n)) returned 9227465 in 2.6 seconds.
(begin (fibo n)) returned 9227465 in 2.61 seconds.
(begin (fibo n)) returned 9227465 in 2.6 seconds.

real	0m7.829s
user	0m7.830s
sys	0m0.000s

Increasing heap size by 65536 after 0 allocated bytes
Number of processors = 8, number of marker threads = 8
Started 7 mark helper threads
Initiating full world-stop collection!

--> Marking for collection 1 after 0 allocated bytes
Collection 0 reclaimed 0 bytes ---> heapsize = 65536 bytes
World-stopped marking took 0 msecs (0 in average)
Heap contains 0 pointer-containing + 0 pointer-free reachable bytes
0 finalization table entries; 0 disappearing links alive
0 objects are eligible for immediate finalization; 0 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Increasing heap size by 65536 after 0 allocated bytes
Adding block map for size of 32 granules (512 bytes)
Adding block map for size of 84 granules (1344 bytes)
Adding block map for size of 0 granules (0 bytes)
Adding block map for size of 3 granules (48 bytes)
Adding block map for size of 2 granules (32 bytes)
Adding block map for size of 1 granules (16 bytes)
Adding block map for size of 17 granules (272 bytes)
Adding block map for size of 5 granules (80 bytes)
Adding block map for size of 4 granules (64 bytes)
Grew fo table to 1 entries
Increasing heap size by 65536 after 99536 allocated bytes
Initiating full world-stop collection!

--> Marking for collection 2 after 103648 allocated bytes
Collection 1 reclaimed 0 bytes ---> heapsize = 196608 bytes
World-stopped marking took 0 msecs (0 in average)
Heap contains 84288 pointer-containing + 14320 pointer-free reachable bytes
1 finalization table entries; 0 disappearing links alive
0 objects are eligible for immediate finalization; 0 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Grew dl table to 1 entries
Adding block map for size of 7 granules (112 bytes)
Adding block map for size of 13 granules (208 bytes)
Adding block map for size of 20 granules (320 bytes)
Grew dl table to 2 entries
Grew dl table to 4 entries
Grew dl table to 8 entries
Adding block map for size of 12 granules (192 bytes)
Adding block map for size of 8 granules (128 bytes)
Grew dl table to 16 entries
Increasing heap size by 69632 after 30592 allocated bytes
Adding block map for size of 42 granules (672 bytes)
Increasing heap size by 90112 after 101760 allocated bytes
Increasing heap size by 122880 after 187344 allocated bytes
Adding block map for size of 9 granules (144 bytes)
Increasing heap size by 684032 after 204432 allocated bytes
Adding block map for size of 15 granules (240 bytes)
Adding block map for size of 16 granules (256 bytes)
Grew dl table to 32 entries
Grew fo table to 2 entries
Grew fo table to 4 entries
Adding block map for size of 18 granules (288 bytes)
Adding block map for size of 6 granules (96 bytes)
Adding block map for size of 11 granules (176 bytes)
Adding block map for size of 10 granules (160 bytes)
Initiating full world-stop collection!

--> Marking for collection 3 after 976880 allocated bytes
Collection 2 reclaimed 4896 bytes ---> heapsize = 1163264 bytes
World-stopped marking took 0 msecs (0 in average)
Heap contains 896752 pointer-containing + 60816 pointer-free reachable bytes
4 finalization table entries; 25 disappearing links alive
0 objects are eligible for immediate finalization; 1 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Increasing heap size by 389120 after 71536 allocated bytes
Increasing heap size by 520192 after 515792 allocated bytes
Initiating full world-stop collection!

--> Marking for collection 4 after 1039104 allocated bytes
Collection 3 reclaimed 78992 bytes ---> heapsize = 2072576 bytes
World-stopped marking took 0 msecs (0 in average)
Heap contains 1259024 pointer-containing + 151616 pointer-free reachable bytes
4 finalization table entries; 26 disappearing links alive
0 objects are eligible for immediate finalization; 0 links cleared
Finalize + initiate sweep took 0 + 0 msecs
Complete collection took 0 msecs
Increasing heap size by 716800 after 103440 allocated bytes
Grew dl table to 64 entries
Adding block map for size of 128 granules (2048 bytes)
(begin (fibo n)) returned 9227465 in 2.78 seconds.
(begin (fibo n)) returned 9227465 in 2.78 seconds.
(begin (fibo n)) returned 9227465 in 2.78 seconds.

real	0m9.213s
user	0m8.350s
sys	0m0.000s

[-- Attachment #3: fibo-with-GC_PRINT_STATS.sig --]
[-- Type: application/octet-stream, Size: 72 bytes --]