Re: out-of-control GC

[Mark H Weaver]

Hi Linas,

Linas Vepstas <address@hidden> writes:

> To make this conversation less crazy, and more down-to-earth, here is a
> demo that seems to spend most of its time in GC. Hard for me to to say that
> this is "wrong", right now, but it illustrates the scandalous nature of the
> problem.
>
> Its a simple loop, about 6 lines of code total, it mostly just wastes cpu
> time.  There's also a longer progress-report printer, similar to the
> previous one I posted.
>
> It runs at about 1 million iterations/minute, for me, of which 15 seconds
> are spent "doing real work", and 45-75 seconds in gc.  Note that GC runs in
> parallel, usually using about 3-4 cores, so the fraction-cpu-time is the
> fraction relative to wall-clock, so that %350 cpu time is typical (i.e. 3.5
> cpu cores are running)
>
> This seems to be a reasonable model of the behavior that I am seeing.

The indentation was stripped from your mail, so I re-indented the
following code:

> ; a tail-recursive loop, seems to waste a lot of time in gc.
> (define (make-bgl lis cnt)
>   ; a bogus longer list
>   (define longer (cons (format #f "~A" cnt) lis))
>   ; periodically report statistics
>   (if (eq? 0 (modulo cnt (* 1000 1000)))
>       (begin (format #t "~A " cnt)  (avg-gc-cpu-time)))
>   ; periodically trim the list
>   (if (eq? 0 (modulo cnt (* 4123 1123)))
>       (set! longer '()))
>   ; loop for a while.
>   (if (eq? 0 cnt) lis
>       (make-bgl longer (- cnt 1))))
>
> ; (define foo (make-bgl '() (* 1235 1000 1000)))

A few observations:

* The (format #f ...) allocates a temporary string output port, and that
  turns out to be quite a lot of allocation, especially in Guile 2.2.
  Glancing at the relevant code, I would estimate that it's at least 2.5
  kilobytes spread over at least 10 heap blocks of various sizes.  It
  also involves registering a finalizer for the port, and adding to a
  weak set, both of which are relatively expensive for the GC to deal
  with.  Using 'number->string' there would reduce memory allocation of
  the loop above by an order of magnitude or more.

  In theory, string ports could (and IMO should) be made a *lot*
  lighter, but we're not there yet.

* The fact that you're using 'set!' to mutate 'longer' forces a
  heap-allocated variable object to be allocated for 'longer', whereas
  otherwise it could be allocated on the stack.  See section 9.3.4
  (Variables and the VM) in the Guile 2.2 manual for more on this, and
  how 'set!' often makes things much less efficient.

* Since 'longer' is allocated within the loop, a new copy of that
  (heap-allocated) variable object is created for each iteration.

Since you're running this loop about 1.2 billion times, and each
iteration is allocating at least 2.5k bytes, that comes out to around 3
terabytes of allocation during this loop.  All of that must be reclaimed
by the garbage collector.

Also, since the port objects have finalizers, they are not deallocated
during the first collection that finds them to be unreachable.  They are
added to a queue of objects to be finalized, and only after they have
been finalized and the next GC runs can they actually be deallocated.

Considering all of this, it's not surprising to me that the cost of this
loop in dominated by time spent in GC.  The remaining things to do are
very lightweight operations by comparison.

       Mark