bug-guile
[Top][All Lists]
Advanced

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

Re: High run time variance


From: Luca Saiu
Subject: Re: High run time variance
Date: Thu, 05 Aug 2010 15:42:03 +0200
User-agent: Mozilla-Thunderbird 2.0.0.22 (X11/20091109)

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

Hello.

Andy Wingo wrote:
> On Mon 29 Mar 2010 18:09, Luca Saiu <address@hidden> writes:
> 
>> To sum up, within each run the computation time of (fibo n) is the same,
>> but the time varies widely from one run to another. This anomaly seems
>> to have become much more accentuated in 1.9.
> 
> I suspect this is related to the GC issues brought up recently on
> guile-user. Something is being misidentified as a Scheme object.

Well, not in the fibo case unless I grossly misunderstood something.
Try running again the same test program q.scm, with GC_PRINT_STATS set
to 1: you will notice that the GC is not triggered at all when computing
fibo, which is correct and good.  I've just checked that this is still
true with 1.9.11; see the attached log.

The run time variance problem is still there in 1.9.11, but it seems
less serious.  I still suspect it's an alignment issue, unrelated to the GC.

By the way, I've been surprised in finding other trivial testcases which
*do* allocate and collect without any obvious reason; see a.scm.

> We'll poke this problem once we have a heap profiler.

That will be fun, indeed.

Thanks and best regards,

- --
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

iEYEARECAAYFAkxav6sACgkQvzOavibF0oYDcQCdGVWvzeKNFITXG6RFo70oqBDW
s6EAn2BOYi6QmfyQvK3ARzGo0sNyWC3X
=2RcI
-----END PGP SIGNATURE-----
address@hidden ~/scratch]$ GC_PRINT_STATS=1 \time -p guile q.scm
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 103584 allocated bytes
Initiating full world-stop collection!

--> Marking for collection 2 after 103600 allocated bytes
Collection 1 reclaimed 0 bytes ---> heapsize = 196608 bytes
World-stopped marking took 0 msecs (0 in average)
Heap contains 84304 pointer-containing + 14272 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)
Grew dl table to 2 entries
Adding block map for size of 13 granules (208 bytes)
Adding block map for size of 20 granules (320 bytes)
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 30656 allocated bytes
Adding block map for size of 42 granules (672 bytes)
Increasing heap size by 90112 after 100448 allocated bytes
Increasing heap size by 122880 after 185792 allocated bytes
Adding block map for size of 9 granules (144 bytes)
Increasing heap size by 684032 after 202832 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 10 granules (160 bytes)
Adding block map for size of 14 granules (224 bytes)
Adding block map for size of 6 granules (96 bytes)
Adding block map for size of 11 granules (176 bytes)
Initiating full world-stop collection!

--> Marking for collection 3 after 973552 allocated bytes
Collection 2 reclaimed 4864 bytes ---> heapsize = 1163264 bytes
World-stopped marking took 10 msecs (3 in average)
Heap contains 896640 pointer-containing + 61136 pointer-free reachable bytes
4 finalization table entries; 26 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
Adding block map for size of 18 granules (288 bytes)
Increasing heap size by 389120 after 91168 allocated bytes
Increasing heap size by 520192 after 505632 allocated bytes
Initiating full world-stop collection!

--> Marking for collection 4 after 1030672 allocated bytes
Collection 3 reclaimed 73152 bytes ---> heapsize = 2072576 bytes
World-stopped marking took 0 msecs (2 in average)
Heap contains 1279280 pointer-containing + 149120 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 220144 allocated bytes
Grew dl table to 64 entries
Initiating full world-stop collection!

--> Marking for collection 5 after 1254672 allocated bytes
Collection 4 reclaimed 581984 bytes ---> heapsize = 2789376 bytes
World-stopped marking took 0 msecs (2 in average)
Heap contains 1837088 pointer-containing + 234592 pointer-free reachable bytes
5 finalization table entries; 41 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
Adding block map for size of 128 granules (2048 bytes)
Increasing heap size by 937984 after 44352 allocated bytes
(begin (fibo n)) returned 9227465 in 2.37 seconds.
(begin (fibo n)) returned 9227465 in 2.37 seconds.
(begin (fibo n)) returned 9227465 in 2.37 seconds.
real 7.14
user 7.13
sys 0.01
;;; Why does this GCs after creating b?  Try running this with GC_PRINT_STATS=1,
;;; or with GC_DONT_GC=1 if you want to see the memory use rise.

(define size 100000)
(define times 100)

(define b (make-bitvector size))

(do ((t 0 (1+ t)))
    ((= t times) 'done)
  (do ((i 0 (1+ i)))
      ((= i size) 'done)
    (bitvector-set! b i #t)))

Attachment: log-with-1.9.11.sig
Description: Binary data

Attachment: a.scm.sig
Description: Binary data


reply via email to

[Prev in Thread] Current Thread [Next in Thread]