From mboxrd@z Thu Jan 1 00:00:00 1970 Path: news.gmane.org!.POSTED!not-for-mail From: Mark H Weaver Newsgroups: gmane.lisp.guile.user Subject: Re: out-of-control GC Date: Tue, 12 Sep 2017 22:24:21 -0400 Message-ID: <87d16ve3oq.fsf@netris.org> References: NNTP-Posting-Host: blaine.gmane.org Mime-Version: 1.0 Content-Type: text/plain X-Trace: blaine.gmane.org 1505342618 1389 195.159.176.226 (13 Sep 2017 22:43:38 GMT) X-Complaints-To: usenet@blaine.gmane.org NNTP-Posting-Date: Wed, 13 Sep 2017 22:43:38 +0000 (UTC) User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/25.2 (gnu/linux) Cc: guile-user@gnu.org To: Linas Vepstas Original-X-From: guile-user-bounces+guile-user=m.gmane.org@gnu.org Wed Sep 13 04:26:39 2017 Return-path: Envelope-to: guile-user@m.gmane.org Original-Received: from lists.gnu.org ([208.118.235.17]) by blaine.gmane.org with esmtp (Exim 4.84_2) (envelope-from ) id 1drxNX-0007Yw-HF for guile-user@m.gmane.org; Wed, 13 Sep 2017 04:26:15 +0200 Original-Received: from localhost ([::1]:39685 helo=lists.gnu.org) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1drxNe-0003kV-Nd for guile-user@m.gmane.org; Tue, 12 Sep 2017 22:26:22 -0400 Original-Received: from eggs.gnu.org ([2001:4830:134:3::10]:57777) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1drxM1-0002qN-RQ for guile-user@gnu.org; Tue, 12 Sep 2017 22:24:42 -0400 Original-Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1drxLy-0002g3-Dm for guile-user@gnu.org; Tue, 12 Sep 2017 22:24:41 -0400 Original-Received: from world.peace.net ([50.252.239.5]:59855) by eggs.gnu.org with esmtps (TLS1.0:RSA_AES_128_CBC_SHA1:16) (Exim 4.71) (envelope-from ) id 1drxLy-0002Nf-9d for guile-user@gnu.org; Tue, 12 Sep 2017 22:24:38 -0400 Original-Received: from [10.1.10.104] (helo=jojen) by world.peace.net with esmtpsa (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.84_2) (envelope-from ) id 1drxLm-0004Kc-QG; Tue, 12 Sep 2017 22:24:26 -0400 In-Reply-To: (Linas Vepstas's message of "Sat, 9 Sep 2017 23:14:46 -0500") X-detected-operating-system: by eggs.gnu.org: GNU/Linux 2.2.x-3.x [generic] [fuzzy] X-Received-From: 50.252.239.5 X-BeenThere: guile-user@gnu.org X-Mailman-Version: 2.1.21 Precedence: list List-Id: General Guile related discussions List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: guile-user-bounces+guile-user=m.gmane.org@gnu.org Original-Sender: "guile-user" Xref: news.gmane.org gmane.lisp.guile.user:14141 Hi Linas, Linas Vepstas 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