Heap exhausted, large arrays

[hjs]

I'm finding that when I do a lot of calcs with big arrays, I'm getting a heap exhausted & sbcl falls into the ldb.

Here's some test code that causes it to happen fairly reliably. Call it foo.lisp:

(eval-when (:compile-toplevel)
  (declaim (optimize (speed 3) (safety 1) (space 0) (debug 0))))

(defun rseq (a b num)
  "Args: (a b num)
Returns a list of NUM equally spaced points starting at A and ending at B."
  (declare (type number a b)
      (type (integer 0 1000000000) num)
      (values cons))
  (let ((d (/ (float (- b a)) (1- num))))
    (loop for i upto (1- num) collect (+ a (* i d)))))

(defun v4* (a b)
  (declare (type (simple-array double-float (*)) a b))
  (assert (eq (length a) (length b)) (a b)
   "Sequence arguments are not of the same length.")
  (map '(simple-array double-float (*)) #'* a b))

(defun testv4 (n m)
  (declare (type (integer 1 10000000) n m))
  (let ((v1 (coerce (rseq 0d0 (1- m) m) '(vector double-float)))
 (v2 (coerce (rseq 0d0 .1d0 m) '(vector double-float))))
    (time (progn (dotimes (i n)
     (setq v1 (v4* v1 v2)))))
    (reduce #'+ v1)))

In SBCL, then do:

(load (compile-file "foo"))

and keep doing:
(testv4 100 1000000)

After enough iterations, I eventually get:

* Heap exhausted during garbage collection: 0 bytes available, 16 requested.
 Gen StaPg UbSta LaSta LUbSt Boxed Unboxed LB LUB !move Alloc Waste Trig WP GCs Mem-age
   0: 24608 0 23685 0 1483 87 0 245 0 59388320 85600 24487962 0 1 0.0000
   1: 32737 32767 0 0 2284 2252 0 735 747 172492624 227504 10737418 1527 0 0.8588
   2: 30066 30418 0 0 3718 3699 0 1470 1243 290840336 368880 59301018 3700 1 0.6286
   3: 9440 14867 0 0 3567 3545 0 1960 1492 296794944 476352 145342330 3545 1 0.4535
   4: 19629 19628 0 0 2938 2689 0 735 753 208150592 319424 2000000 2920 0 0.0000
   5: 0 0 0 0 0 0 0 0 0 0 0 2000000 0 0 0.0000
   6: 0 0 0 0 1196 165 0 0 0 44597248 0 2000000 1116 0 0.0000
   Total bytes allocated = 1072264064
   Dynamic-space-size bytes = 1073741824
GC control variables:
   *GC-INHIBIT* = true
   *GC-PENDING* = true
   *STOP-FOR-GC-PENDING* = false
fatal error encountered in SBCL pid 8253(tid 140737353930560):
Heap exhausted, game over.

Welcome to LDB, a low-level debugger for the Lisp runtime environment.
ldb>

I realize the above code creates a log of garbage, but I'm not holding onto it. Shouldn't the GC reclaim it?

Details:

In stock Linux Mint 17.1 sbcl:

~/lisp/cls$ sbcl --version
SBCL 1.1.14.debian

But I also reporduced

~/lisp/cls$ uname -a
Linux hjstein-ThinkPad-X1-Carbon-2nd 3.13.0-37-generic #64-Ubuntu SMP Mon Sep 22 21:28:38 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux

~/lisp/cls$ sbcl
This is SBCL 1.1.14.debian, an implementation of ANSI Common Lisp.
More information about SBCL is available at <http://www.sbcl.org/>.

SBCL is free software, provided as is, with absolutely no warranty.
It is mostly in the public domain; some portions are provided under
BSD-style licenses. See the CREDITS and COPYING files in the
distribution for more information.
* *features*

(:QUICKLISP :SB-BSD-SOCKETS-ADDRINFO :ASDF3 :ASDF2 :ASDF :OS-UNIX
 :NON-BASE-CHARS-EXIST-P :ASDF-UNICODE :ALIEN-CALLBACKS :ANSI-CL
 :ASH-RIGHT-VOPS :C-STACK-IS-CONTROL-STACK :COMMON-LISP :COMPARE-AND-SWAP-VOPS
 :COMPLEX-FLOAT-VOPS :CYCLE-COUNTER :ELF :FLOAT-EQL-VOPS :GENCGC
 :IEEE-FLOATING-POINT :INLINE-CONSTANTS :LARGEFILE :LINKAGE-TABLE :LINUX
 :LITTLE-ENDIAN :MEMORY-BARRIER-VOPS :MULTIPLY-HIGH-VOPS :OS-PROVIDES-BLKSIZE-T
 :OS-PROVIDES-DLADDR :OS-PROVIDES-DLOPEN :OS-PROVIDES-GETPROTOBY-R
 :OS-PROVIDES-POLL :OS-PROVIDES-PUTWC :OS-PROVIDES-SUSECONDS-T
 :PACKAGE-LOCAL-NICKNAMES :RAW-INSTANCE-INIT-VOPS :SB-CORE-COMPRESSION :SB-DOC
 :SB-EVAL :SB-FUTEX :SB-LDB :SB-PACKAGE-LOCKS :SB-SIMD-PACK
 :SB-SOURCE-LOCATIONS :SB-TEST :SB-THREAD :SB-UNICODE :SBCL
 :STACK-ALLOCATABLE-CLOSURES :STACK-ALLOCATABLE-FIXED-OBJECTS
 :STACK-ALLOCATABLE-LISTS :STACK-ALLOCATABLE-VECTORS
 :STACK-GROWS-DOWNWARD-NOT-UPWARD :UNIX :UNWIND-TO-FRAME-AND-CALL-VOP :X86-64)
*

Also in latest version:

~/lisp/cls$ /home/hjstein/Software/sbcl/bin/sbcl --version
SBCL 1.2.7

* *features*

(:QUICKLISP :SB-BSD-SOCKETS-ADDRINFO :ASDF-PACKAGE-SYSTEM :ASDF3.1 :ASDF3
 :ASDF2 :ASDF :OS-UNIX :NON-BASE-CHARS-EXIST-P :ASDF-UNICODE :ALIEN-CALLBACKS
 :ANSI-CL :ASH-RIGHT-VOPS :C-STACK-IS-CONTROL-STACK :COMMON-LISP
 :COMPARE-AND-SWAP-VOPS :CYCLE-COUNTER :ELF :GENCGC :IEEE-FLOATING-POINT
 :INLINE-CONSTANTS :LARGEFILE :LINKAGE-TABLE :LINUX :LITTLE-ENDIAN
 :MEMORY-BARRIER-VOPS :MULTIPLY-HIGH-VOPS :OS-PROVIDES-BLKSIZE-T
 :OS-PROVIDES-DLADDR :OS-PROVIDES-DLOPEN :OS-PROVIDES-GETPROTOBY-R
 :OS-PROVIDES-POLL :OS-PROVIDES-PUTWC :OS-PROVIDES-SUSECONDS-T
 :PACKAGE-LOCAL-NICKNAMES :RAW-INSTANCE-INIT-VOPS :SB-DOC :SB-EVAL :SB-FUTEX
 :SB-LDB :SB-PACKAGE-LOCKS :SB-SOURCE-LOCATIONS :SB-TEST :SB-THREAD :SB-UNICODE
 :SBCL :STACK-ALLOCATABLE-CLOSURES :STACK-ALLOCATABLE-FIXED-OBJECTS
 :STACK-ALLOCATABLE-LISTS :STACK-ALLOCATABLE-VECTORS
 :STACK-GROWS-DOWNWARD-NOT-UPWARD :SYMBOL-INFO-VOPS :UNIX
 :UNWIND-TO-FRAME-AND-CALL-VOP :X86)

[hjs (hjstein)]

It seems to be a combination compiler/gc bug, because I don't run out of memory when I take the declaration out of the definition of v*. So, consider the attached code. Just load it into sbcl to see the crash.

Take a look at the total bytes allocated in the gc log files with gnuplot, and a command like:

plot "< awk '/Total bytes/ {n++ ; print n, $5}' testgc4-ok.log" w l, "< awk '/Total bytes/ {n++ ; print n, $5}' testgc4-crash.log" w l

Without the declaration, it doesn't grow too much over time. With the declaration, it keeps ratcheting up until the heap is exhausted.

I just built SBCL 1.2.10.72-c2a4aec, and it's not as bad. It can survive many calls to testcrash with 1mb arrays, and appears to use less memory in general. However, it's still the case that far more memory is used when the declaration is used, and it crashes pretty quickly when using 2mb arrays.

Also, I find the amount of garbage being retained to be surprising. A 2mb array of doubles is just 16mb, and only 3 are active at any time, which accounts for 48mb, yet the memory usage is becoming as 700mb. Use 5mb arrays instead, for a footprint of 120mb, and it quickly is unable to GC & crashes.

[Jim Newton (jimka-issy)]

I posted this already in comp.lang.lisp, but I'll re-post it here.

I have a program which demonstrates this issue.
Maybe I'm really allocating more memory than my machine has?

(defclass cell ()
  ((data :initarg :data)))

(defun test-allocate (x)
  (declare (optimize (safety 3) (debug 3) (space 0) (speed 0)))

  (let ((w 2562)
        (h 1602)
        (d 3))
    (let ((arr2d (make-array (list w h)))
          (arr3d (make-array (list w h d))))

      (dotimes (i w)
        (dotimes (j h)
          (let ((vec (make-array (list d))))
            (let ((value (make-instance 'cell :data vec)))
              (setf (aref arr2d i j) value)
              (dotimes (k d)
                (setf (aref vec k) x))))))

      (dotimes (i w)
        (dotimes (j h)
          (dotimes (k d)
            (setf (aref arr3d i j k) x))))

      (list arr2d arr3d))))

(test-allocate 3.1)

* Heap exhausted during garbage collection: 0 bytes available, 32 requested.
 Gen StaPg UbSta LaSta LUbSt Boxed Unboxed LB LUB !move Alloc Waste Trig WP GCs Mem-age
   0: 0 0 0 0 0 0 0 0 0 0 0 10737418 0 0 0.0000
   1: 0 0 0 0 0 0 0 0 0 0 0 10737418 0 0 0.0000
   2: 1515 0 0 0 14529 90 0 0 43 478264576 770816 2000000 0 0 2.1092
   3: 0 0 0 0 0 0 0 0 0 0 0 2000000 0 0 0.0000
   4: 0 0 0 0 0 0 0 0 0 0 0 2000000 0 0 0.0000
   5: 0 0 0 0 0 0 0 0 0 0 0 2000000 0 0 0.0000
   6: 0 0 0 0 1220 241 0 0 0 47874048 0 2000000 1092 0 0.0000
   Total bytes allocated = 1072272272
   Dynamic-space-size bytes = 1073741824
GC control variables:
   *GC-INHIBIT* = true
   *GC-PENDING* = true
fatal error encountered in SBCL pid 9337:

[Jim Newton (jimka-issy)]

Thanks Pascal Bourguignon for helping me find what seems to be a workaround.
If I start sbcl with the command line as follows, the test seems to run without exhausting the heap.

csh> sbcl --dynamic-space-size 3741824

I'm not sure what the original heap size was. From the error message output perhaps it was
(Dynamic-space-size bytes) 1073741824. In which case 3741824 is two orders of magnitude smaller.

[Attila Lendvai (attila-lendvai)]

when i write code, for clarity i keep such values in their units, unless there's a good reason not to. (it's a tough call in this case whether the unit is bits or bytes though...)

but --dynamic-space-size uses megabytes.

http://www.sbcl.org/manual/#Runtime-Options

[Pascal J. Bourguignon (pjb-informatimago)]

Here is another use case. Basically: allocate a TEMPORARY string of 200M characters, (it's not referenced after the form is evaluated, not even in *); then allocate a vector of 200M octets. There is no exhaustion, because the 200M character string is garbage and it should be collected SILENTLY!

[pjb@despina :0.0 ~]$ sbcl --no-userinit
This is SBCL 1.4.1, an implementation of ANSI Common Lisp.
More information about SBCL is available at <http://www.sbcl.org/>.

SBCL is free software, provided as is, with absolutely no warranty.
It is mostly in the public domain; some portions are provided under
BSD-style licenses. See the CREDITS and COPYING files in the
distribution for more information.
* (let ((string (make-string (* 200 1024 1024) :initial-element #\a))
        (pattern "07123E1F482356C415F684407A3B8723E10B2CBBC0B8FCD6282C49D37C9C1ABC"))
     (replace string pattern :start1 (- (length string) (length pattern)))
     (time (search pattern string)))

Evaluation took:
  2.012 seconds of real time
  2.010401 seconds of total run time (2.007339 user, 0.003062 system)
  99.90% CPU
  8,065,801,078 processor cycles
  0 bytes consed

209715136
* (let ((string (make-array (* 200 1024 1024) :element-type '(unsigned-byte 8) :initial-element (char-code #\a)))
        (pattern (map '(vector (unsigned-byte 8)) 'char-code "07123E1F482356C415F684407A3B8723E10B2CBBC0B8FCD6282C49D37C9C1ABC")))
    (replace string pattern :start1 (- (length string) (length pattern)))
    (time (search pattern string)))
Heap exhausted during allocation: 204046336 bytes available, 209715216 requested.
 Gen StaPg UbSta LaSta Boxed Unbox LB LUB !move Alloc Waste Trig WP GCs Mem-age
   0: 26538 0 0 45 0 0 0 0 1405408 69152 10737418 0 0 0.0000
   1: 26524 26512 0 19 2 0 25601 25608 839364224 217472 2000000 7 0 0.0000
   2: 0 0 0 0 0 0 0 0 0 0 2000000 0 0 0.0000
   3: 0 0 0 0 0 0 0 0 0 0 2000000 0 0 0.0000
   4: 0 0 0 0 0 0 0 0 0 0 2000000 0 0 0.0000
   5: 0 0 0 0 0 0 0 0 0 0 2000000 0 0 0.0000
   6: 0 0 0 570 304 0 0 0 27930768 708464 2000000 553 0 0.0000
   7: 875 876 0 0 0 0 0 0 0 0 2000000 0 0 0.0000
   Total bytes allocated = 868700400
   Dynamic-space-size bytes = 1073741824
GC control variables:
   *GC-INHIBIT* = false
   *GC-PENDING* = true
   *STOP-FOR-GC-PENDING* = false

debugger invoked on a SB-KERNEL::HEAP-EXHAUSTED-ERROR in thread
#<THREAD "main thread" RUNNING {1001B50083}>:
  Heap exhausted (no more space for allocation).
204046336 bytes available, 209715216 requested.

PROCEED WITH CAUTION.

Type HELP for debugger help, or (SB-EXT:EXIT) to exit from SBCL.

restarts (invokable by number or by possibly-abbreviated name):
  0: [ABORT] Exit debugger, returning to top level.

(SB-KERNEL::HEAP-EXHAUSTED-ERROR 102023168 104857608)
0] :a

* (let ((string (make-array (* 200 1024 1024) :element-type '(unsigned-byte 8...