I was able to reduce the problem to a simple test case: Compile and
load the file 'foo.lisp' below in a fresh CMUCL image. Then evaluate
(TEST 1000)
a couple of times. Now do the same thing but with
(TEST 1000 T)
instead. On my machine (CMUCL 18e, Linux x86) in the first case the
output always looks more or less like this [partly snipped for
brevity]:
* (test 1000)
; Evaluation took: ;;; this is LOAD
; 6.88 seconds of real time
; [Run times include 2.2 seconds GC run time]
; 160,029,728 bytes consed.
; [GC threshold exceeded with 52,636,080 bytes in use. Commencing GC.]
; [GC completed with 1,080,872 bytes retained and 51,555,208 bytes freed.]
; [GC will next occur when at least 21,080,872 bytes are in use.]
; Evaluation took: ;;; this is EXT:GC
; 0.2 seconds of real time
NIL
However, in the second case this is what I get from a freshly-started
CMUCL:
* (test 1000 t)
; Evaluation took: ;;; this is LOAD
; 12.59 seconds of real time
; [Run times include 7.24 seconds GC run time]
; 160,037,752 bytes consed.
; [GC threshold exceeded with 160,978,472 bytes in use. Commencing GC.]
; [GC completed with 51,982,504 bytes retained and 108,995,968 bytes freed.]
; [GC will next occur when at least 71,982,504 bytes are in use.]
; Evaluation took: ;;; this is EXT:GC
; 7.94 seconds of real time
NIL
* (test 1000 t)
; Evaluation took: ;;; this is LOAD
; 13.2 seconds of real time
; [Run times include 7.81 seconds GC run time]
; 160,037,752 bytes consed.
; [GC threshold exceeded with 160,976,824 bytes in use. Commencing GC.]
; [GC completed with 156,313,784 bytes retained and 4,663,040 bytes freed.]
; [GC will next occur when at least 176,313,784 bytes are in use.]
; Evaluation took: ;;; this is EXT:GC
; 21.08 seconds of real time
NIL
* (test 1000 t)
; Evaluation took: ;;; this is LOAD
; 13.11 seconds of real time
; [Run times include 7.76 seconds GC run time]
; 0 page faults and
; 160,037,752 bytes consed.
; [GC threshold exceeded with 160,977,032 bytes in use. Commencing GC.]
; [GC completed with 118,550,080 bytes retained and 42,426,952 bytes freed.]
; [GC will next occur when at least 138,550,080 bytes are in use.]
; Evaluation took: ;;; this is EXT:GC
; 16.4 seconds of real time
NIL
Now, for the third test, if I remove the explicit GC calls from
foo.lisp and evaluate (TEST 1000 T) then it takes longer each time I
call it (which is due to GC run time as reported by TIME). After about
four calls I end up with something like
* (test 1000 t)
!!! CMUCL has run out of dynamic heap space. You can control heap size
!!! with the -dynamic-space-size commandline option.
*A2 gc_alloc_new_region failed, nbytes=8.
Generation Boxed Unboxed LB LUB Alloc Waste Trig WP GCs Mem-age
0: 0 0 0 0 0 0 2000000 0 0 0.0000
1: 27218 0 0 0 111462720 22208 2000000 0 0 1.0772
2: 84661 65 0 0 346994672 43024 2000000 84659 0 0.6166
3: 0 0 0 0 0 0 2000000 0 0 0.0000
4: 0 0 0 0 0 0 2000000 0 0 0.0000
5: 0 0 0 0 0 0 2000000 0 0 0.0000
6: 19128 0 0 0 78345016 3272 0 0 0 0.0000
Total bytes alloc=536802408
Does that help? Does this also happen with Solaris?
Cheers,
Edi.
------------------- foo.lisp -------------------------
(defun cons-a-lot (n)
(if (zerop n)
(list 'progn)
`(progn ,(cons-a-lot (1- n)))))
(defun foo-reader (stream char arg)
(declare (ignore arg char))
(cons-a-lot
(* 1000
(loop for char = (peek-char nil stream t nil t)
while (alphanumericp char)
do (read-char stream t nil t)
count t))))
(defun test-gc (&optional verbose)
(let ((ext:*gc-verbose* verbose))
(ext:gc :full t)))
(defun test (n &optional one-form)
(let ((ext:*gc-verbose* nil)
(*readtable* (copy-readtable)))
(set-dispatch-macro-character #\# #\? #'foo-reader)
(with-open-file (s "foo-test.lisp"
:direction :output
:if-exists :supersede)
(when one-form
(format s "(progn~%"))
(loop for i below n
do (format s "#?eeeeeeeeee~%"))
(when one-form
(format s ")~%")))
(test-gc)
(time (load "foo-test.lisp"))
(time (test-gc t))))
