gencgc lazy in releasing memory back to the OS

[Nikodemus Siivola]

Regression from:

commit 6848a92fd4af23d0695eeaaed9efcbdfd9e1d9e5
Author: Nikodemus Siivola <email address hidden>
Date: Sat Nov 19 16:35:18 2011 +0200

    default gen.bytes_consed_between_gc to same 5% of dynamic space size

      ...the previous default was 2,000,000 bytes, not 20Mb as the
      documentation claimed. Oops.

Test case:

;;; Run with --dynamic-space-size 8Gb --script ~/this-file.lisp

(setf (bytes-consed-between-gcs) (* 400 1024 1024))

(ignore-errors
 (delete-directory "~/.cache/common-lisp/" :recursive t))

(require :sb-posix)

(let ((quicklisp-init (merge-pathnames "quicklisp/setup.lisp"
                                       (user-homedir-pathname))))
  (when (probe-file quicklisp-init)
    (load quicklisp-init)))

(defvar *pid* (princ-to-string (sb-posix:getpid)))

(defvar *log* "/tmp/top.log")

(defvar *top*
  #+darwin
  (run-program "top" (list "-c" "e" "-l" "0" "-pid" *pid*)
               :search t :wait nil
               :output *log* :if-output-exists :supersede)
  #-darwin
  (run-program "top" (list "-b" (format nil "-p~A" *pid*))
               :search t :wait nil
               :output *log* :if-output-exists :supersede))

(let ((time
        (with-output-to-string (*trace-output*)
          (unwind-protect
               (time
                (let ((*standard-output* (make-broadcast-stream)))
                  (mapc
                   'ql:quickload
                   '(closer-mop cl-ppcre cxml cxml-stp closure-html drakma named-readtables
                     iterate cffi trivial-garbage bordeaux-threads chipz trivial-gray-streams
                     conium prepl osicat command-line-arguments cl-pdf cl-typesetting postmodern
                     alexandria csv-parser ironclad cl-json ht-simple-ajax hunchentoot local-time
                     vecto simple-date cl-who cl-jpeg salza2))))
            ;; Give time for top to grab the last snapshot.
            (sleep 1)
            (process-kill *top* sb-unix::sigkill :process-group)))))
  (format t "~%; --------------------------------------------------------------~%; SBCL ~A~%"
          (lisp-implementation-version))
  (with-input-from-string (time time)
    (loop for line = (read-line time nil)
          while line
          do (write-string "; ")
             (write-line line))))

(with-open-file (f *log*)
  ;; Header
  (loop for line = (read-line f)
        until (search "PID" line)
        finally (format t "; ~A~%" line))
  (loop for line = (read-line f nil)
        while line
        when (search "sbcl" line)
        do (format t "; ~A~%" line)))

Before regression:

; --------------------------------------------------------------
; SBCL 1.0.53.45-3cd198e
; Evaluation took:
; 98.920 seconds of real time
; 97.530094 seconds of total run time (93.953871 user, 3.576223 system)
; [ Run times consist of 3.168 seconds GC time, and 94.363 seconds non-GC time. ]
; 98.59% CPU
; 63,038 forms interpreted
; 147,230 lambdas converted
; 197,344,199,770 processor cycles
; 11,353,474,992 bytes consed
;
; PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
; 28653 nikodemu 20 0 8248m 418m 24m R 98 10.8 0:03.82 sbcl
; 28653 nikodemu 20 0 8248m 444m 25m R 100 11.4 0:06.82 sbcl
; 28653 nikodemu 20 0 8248m 462m 25m R 100 11.9 0:09.81 sbcl
; 28653 nikodemu 20 0 8248m 464m 25m R 100 11.9 0:12.80 sbcl
; 28653 nikodemu 20 0 8248m 480m 25m R 100 12.4 0:15.79 sbcl
; 28653 nikodemu 20 0 8248m 496m 25m R 99 12.8 0:18.77 sbcl
; 28653 nikodemu 20 0 8248m 114m 25m R 100 2.9 0:21.77 sbcl
; 28653 nikodemu 20 0 8248m 449m 26m R 99 11.6 0:24.74 sbcl
; 28653 nikodemu 20 0 8248m 479m 26m R 100 12.3 0:27.74 sbcl
; 28653 nikodemu 20 0 8248m 281m 26m R 100 7.2 0:30.73 sbcl
; 28653 nikodemu 20 0 8248m 488m 26m R 100 12.6 0:33.72 sbcl
; 28653 nikodemu 20 0 8248m 544m 26m R 100 14.0 0:36.72 sbcl
; 28653 nikodemu 20 0 8248m 545m 26m R 100 14.0 0:39.73 sbcl
; 28653 nikodemu 20 0 8248m 584m 26m R 100 15.0 0:42.72 sbcl
; 28653 nikodemu 20 0 8256m 584m 27m R 100 15.0 0:45.72 sbcl
; 28653 nikodemu 20 0 8256m 584m 27m R 100 15.0 0:48.73 sbcl
; 28653 nikodemu 20 0 8256m 388m 27m R 99 10.0 0:51.70 sbcl
; 28653 nikodemu 20 0 8256m 498m 27m S 84 12.8 0:54.22 sbcl
; 28653 nikodemu 20 0 8260m 515m 27m R 78 13.2 0:56.56 sbcl
; 28653 nikodemu 20 0 8260m 515m 27m R 100 13.2 0:59.55 sbcl
; 28653 nikodemu 20 0 8260m 517m 27m R 100 13.3 1:02.54 sbcl
; 28653 nikodemu 20 0 8260m 393m 27m R 100 10.1 1:05.53 sbcl
; 28653 nikodemu 20 0 8260m 517m 27m R 100 13.3 1:08.53 sbcl
; 28653 nikodemu 20 0 8260m 541m 27m R 100 13.9 1:11.53 sbcl
; 28653 nikodemu 20 0 8260m 542m 27m R 100 13.9 1:14.54 sbcl
; 28653 nikodemu 20 0 8260m 550m 27m R 100 14.1 1:17.54 sbcl
; 28653 nikodemu 20 0 8260m 550m 27m R 100 14.1 1:20.53 sbcl
; 28653 nikodemu 20 0 8260m 569m 27m R 100 14.6 1:23.54 sbcl
; 28653 nikodemu 20 0 8260m 569m 27m R 100 14.6 1:26.53 sbcl
; 28653 nikodemu 20 0 8260m 354m 27m R 100 9.1 1:29.53 sbcl
; 28653 nikodemu 20 0 8260m 568m 27m R 100 14.6 1:32.53 sbcl
; 28653 nikodemu 20 0 8260m 592m 27m R 100 15.2 1:35.53 sbcl
; 28653 nikodemu 20 0 8260m 598m 27m R 100 15.4 1:38.52 sbcl
; 28653 nikodemu 20 0 8260m 598m 27m S 78 15.4 1:40.86 sbcl

After regression:

; --------------------------------------------------------------
; SBCL 1.0.53.47-6848a92
; Evaluation took:
; 127.235 seconds of real time
; 120.047502 seconds of total run time (117.551346 user, 2.496156 system)
; [ Run times consist of 3.121 seconds GC time, and 116.927 seconds non-GC time. ]
; 94.35% CPU
; 63,038 forms interpreted
; 147,230 lambdas converted
; 253,832,697,170 processor cycles
; 11,354,749,872 bytes consed
;
; PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
; 912 nikodemu 20 0 8248m 414m 23m R 90 10.7 0:04.48 sbcl
; 912 nikodemu 20 0 8248m 450m 25m R 89 11.6 0:07.14 sbcl
; 912 nikodemu 20 0 8248m 451m 25m R 93 11.6 0:09.92 sbcl
; 912 nikodemu 20 0 8248m 451m 25m R 93 11.6 0:12.70 sbcl
; 912 nikodemu 20 0 8248m 467m 25m R 90 12.0 0:15.41 sbcl
; 912 nikodemu 20 0 8248m 467m 25m R 93 12.0 0:18.19 sbcl
; 912 nikodemu 20 0 8248m 467m 25m R 96 12.0 0:21.08 sbcl
; 912 nikodemu 20 0 8248m 495m 25m R 97 12.7 0:24.00 sbcl
; 912 nikodemu 20 0 8248m 511m 25m R 97 13.1 0:26.92 sbcl
; 912 nikodemu 20 0 8248m 511m 26m R 97 13.1 0:29.83 sbcl
; 912 nikodemu 20 0 8248m 286m 26m R 96 7.4 0:32.71 sbcl
; 912 nikodemu 20 0 8248m 480m 26m R 95 12.3 0:35.56 sbcl
; 912 nikodemu 20 0 8248m 490m 26m R 94 12.6 0:38.39 sbcl
; 912 nikodemu 20 0 8248m 507m 26m R 97 13.0 0:41.30 sbcl
; 912 nikodemu 20 0 8248m 532m 26m R 97 13.7 0:44.22 sbcl
; 912 nikodemu 20 0 8248m 578m 26m R 97 14.9 0:47.13 sbcl
; 912 nikodemu 20 0 8248m 578m 26m R 98 14.9 0:50.07 sbcl
; 912 nikodemu 20 0 8256m 585m 27m R 96 15.0 0:52.96 sbcl
; 912 nikodemu 20 0 8256m 633m 27m R 98 16.3 0:55.91 sbcl
; 912 nikodemu 20 0 8256m 633m 27m R 99 16.3 0:58.87 sbcl
; 912 nikodemu 20 0 8256m 633m 27m R 97 16.3 1:01.78 sbcl
; 912 nikodemu 20 0 8256m 634m 27m R 98 16.3 1:04.71 sbcl
; 912 nikodemu 20 0 8256m 634m 27m R 51 16.3 1:06.25 sbcl
; 912 nikodemu 20 0 8260m 634m 27m R 95 16.3 1:09.11 sbcl
; 912 nikodemu 20 0 8260m 643m 27m R 95 16.5 1:11.95 sbcl
; 912 nikodemu 20 0 8260m 656m 27m R 93 16.9 1:14.75 sbcl
; 912 nikodemu 20 0 8260m 656m 27m R 96 16.9 1:17.63 sbcl
; 912 nikodemu 20 0 8260m 668m 27m R 96 17.2 1:20.51 sbcl
; 912 nikodemu 20 0 8260m 668m 27m R 96 17.2 1:23.40 sbcl
; 912 nikodemu 20 0 8260m 670m 27m R 97 17.2 1:26.30 sbcl
; 912 nikodemu 20 0 8260m 687m 27m R 94 17.7 1:29.13 sbcl
; 912 nikodemu 20 0 8260m 687m 27m R 94 17.7 1:31.96 sbcl
; 912 nikodemu 20 0 8260m 687m 27m R 96 17.7 1:34.84 sbcl
; 912 nikodemu 20 0 8260m 690m 27m R 96 17.7 1:37.73 sbcl
; 912 nikodemu 20 0 8260m 714m 27m R 96 18.4 1:40.60 sbcl
; 912 nikodemu 20 0 8260m 714m 27m R 95 18.4 1:43.44 sbcl
; 912 nikodemu 20 0 8260m 714m 27m R 95 18.4 1:46.29 sbcl
; 912 nikodemu 20 0 8260m 714m 27m R 94 18.4 1:49.12 sbcl
; 912 nikodemu 20 0 8260m 714m 27m R 95 18.4 1:51.98 sbcl
; 912 nikodemu 20 0 8260m 733m 27m R 94 18.9 1:54.80 sbcl
; 912 nikodemu 20 0 8260m 739m 27m R 96 19.0 1:57.69 sbcl
; 912 nikodemu 20 0 8260m 768m 27m R 97 19.7 2:00.61 sbcl
; 912 nikodemu 20 0 8260m 768m 27m R 95 19.7 2:03.46 sbcl

[Nikodemus Siivola (nikodemus)]

commit 661bcd7d3e0bdc1966f3878fa71d322ffd5927a4
Author: Nikodemus Siivola <email address hidden>
Date: Sun Apr 29 20:06:45 2012 +0300

    gencgc: scale generation.bytes_consed_between_gc to number of gens

      This means we have by default 5% of total heap usable in the nursery
      between GCs, and another 5% of the total heap split between all the
      generations -- and roughly matches the nursery/old generation sizes
      relations from before the dynamic-space-size based scaling.

      Fixes lp#991293, regression since
      6848a92fd4af23d0695eeaaed9efcbdfd9e1d9e5.

[Nikodemus Siivola (nikodemus)]

in SBCL 1.0.57