[gambit-list] Real-time or generational gc?

sarna sarna.dev at protonmail.com
Sun Nov 10 01:55:15 EST 2019


Oh, of course it was caused by a bug in my code.. I have much yet to learn. Thank you for the thorough explanation, Marc :)

— sarna

On Sun, Nov 10, 2019 at 04:07, Marc Feeley <feeley at iro.umontreal.ca> wrote:

> When I run your code translated to Gambit Scheme I indeed get GC pauses that increase up to ~600 ms, roughly doubling the pause time from one GC to the next (which makes sense because Gambit’s runtime system is roughly doubling the size of the heap at each GC and the number of live objects also doubles):
>
> *** GC: 807us, 2.9M alloc, 8.0M heap, 2.3M live (28% 2359088+24192)
> *** GC: 1.1ms, 5.5M alloc, 14M heap, 4.9M live (35% 5127344+50912)
> *** GC: 2.7ms, 11M alloc, 27M heap, 10M live (39% 10869056+108192)
> *** GC: 5.1ms, 23M alloc, 54M heap, 23M live (42% 23471344+247392)
> *** GC: 12ms, 48M alloc, 112M heap, 47M live (43% 49220848+525984)
> *** GC: 28ms, 100M alloc, 232M heap, 100M live (43% 103879840+1181280)
> *** GC: 61ms, 209M alloc, 486M heap, 211M live (44% 219043008+2623104)
> *** GC: 131ms, 439M alloc, 1019M heap, 444M live (44% 460264320+5768960)
> *** GC: 276ms, 932M alloc, 2.1G heap, 952M live (44% 977783104+20973224)
> *** GC: 616ms, 1.9G alloc, 4.5G heap, 2.0G live (44% 2085153536+18876032)
>
> I read the blog post and the racket program is written to reach a steady state, so the GC pauses should reach a plateau for a few GCs. The program writes 2 millions messages to a circular buffer of messages of length 200,000, where each message is a 1024 byte u8vector.
>
> However your program is not a faithful translation of the racket program (even disregarding the fact that it uses immutable hash tables). The if condition in push-msg is incorrect… it never deletes old messages when 200,000 have been accumulated, so the program will keep adding messages until all 2 million messages are in the hash table, which is 10 times more than the racket program.
>
> When this bug is fixed the GC pauses become:
>
> *** GC: 817us, 2.9M alloc, 8.0M heap, 2.3M live (28% 2359088+24192)
> *** GC: 1.2ms, 5.5M alloc, 14M heap, 4.9M live (35% 5127344+50912)
> *** GC: 2.6ms, 11M alloc, 27M heap, 10M live (39% 10869056+108192)
> *** GC: 5.1ms, 23M alloc, 54M heap, 23M live (42% 23471344+247392)
> *** GC: 13ms, 48M alloc, 112M heap, 47M live (43% 49220848+525984)
> *** GC: 27ms, 100M alloc, 232M heap, 100M live (43% 103879840+1181280)
> *** GC: 62ms, 209M alloc, 486M heap, 211M live (44% 219043008+2623104)
> *** GC: 113ms, 439M alloc, 917M heap, 400M live (44% 414477968+5244672)
> *** GC: 80ms, 885M alloc, 917M heap, 400M live (44% 414477968+5244672)
> *** GC: 77ms, 1.3G alloc, 917M heap, 400M live (44% 414477968+5244672)
> *** GC: 73ms, 1.7G alloc, 917M heap, 400M live (44% 414477968+5244672)
> *** GC: 73ms, 2.2G alloc, 917M heap, 400M live (44% 414477968+5244672)
> *** GC: 74ms, 2.6G alloc, 917M heap, 400M live (44% 414477968+5244672)
> *** GC: 76ms, 3.0G alloc, 917M heap, 400M live (44% 414477968+5244672)
> *** GC: 73ms, 3.5G alloc, 917M heap, 400M live (44% 414477968+5244672)
>
> So the GC pauses when the hash table contains 200,000 messages are about 75 ms long.
>
> Using a simple 200,000 element vector as a circular buffer, instead of the hash table, reduce the pauses to ~50 ms.
>
> Note that if this circular buffer is really the performance bottleneck of the app then the FFI could be used to allocate a C array as the circular buffer, and use still u8vectors for the messages. An hour’s work at most! The GC would have very little work to do in that case.
>
> Marc
>
>> On Nov 9, 2019, at 12:26 PM, sarna <sarna.dev at protonmail.com> wrote:
>>
>> Hey all,
>>
>> I'm a Scheme noob, please be gentle :)
>>
>> Yes, the Racket code isn't equivalent - it uses immutable hashes instead of mutable ones. I couldn't find immutable ones in Gerbil's docs. Mutable ones should be less of a concern for the GC though, right?
>>
>> The code was adopted from this blog post:
>> http://prl.ccs.neu.edu/blog/2016/05/24/measuring-gc-latencies-in-haskell-ocaml-racket/
>>
>> The Gerbil code itself:
>>
>> (import :std/iter)
>> (import :gerbil/gambit/os)
>> ;; (declare (fixnum))
>> (gc-report-set! #t)
>> ;; (export main)
>>
>> (define window-size 200000)
>> (define msg-count 2000000)
>>
>> (define (message n) (make-u8vector 1024 (modulo n 256)))
>>
>> (define (push-msg chan id-high)
>> (define id-low (- id-high window-size))
>> (define inserted
>> (begin
>> (hash-put! chan id-high (message id-high))
>> chan))
>> (if (hash-get inserted (< id-low 0))
>> (hash-remove! inserted id-low)))
>>
>> (define (main)
>> (time
>> (for/fold
>> (chan (make-hash-table))
>> (i (in-range msg-count))
>> (begin
>> (push-msg chan i)
>> chan))))
>>
>> (main)
>>
>> Running it with gxi produces a peak ~840ms (!) pause. Compiling it with gxc (after commenting (main) and uncommenting (export main)) and running it produces a peak 637ms pause - that's still more than half a second.
>>
>> -- sarna
>>
>> ‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐
>> On Saturday, November 9, 2019 4:50 PM, Dimitris Vyzovitis <vyzo at hackzen.org> wrote:
>>
>>> CC'ing sarna, who found the pathology.
>>> The u8vectors were smaller than the still limit, so they were being moved around.
>>>
>>> -- vyzo
>>>
>>> On Sat, Nov 9, 2019 at 5:44 PM Marc Feeley <feeley at iro.umontreal.ca> wrote:
>>>
>>> > On Nov 9, 2019, at 10:02 AM, Dimitris Vyzovitis <vyzo at hackzen.org> wrote:
>>> >
>>> > Thanks Marc!
>>> >
>>> > Just to be clear, the pause times are not currently causing an issue for me.
>>> >
>>> > There is a gerbil however who has been investigating pause times and found a pathological program that allocates u8vectors and stuffs them into a hash table. In that case, there is an accumulation of memory, leading to pause times of 500-600ms, while racket averages 20ms (with a peak of about 170ms) on the equivalent program. This is clearly an artifact of generational gc, but it always vexes me when racket seemingly does better at something :p
>>> >
>>> > -- vyzo
>>>
>>> It would be good to investigate this further because the behaviour you describe is not the one I would have expected, assuming the u8vectors are not small (i.e. >= 2033 bytes on a 64 bit machine). That’s because non-small objects are allocated as still objects and aren’t moved by the GC and the content isn’t even looked at by the GC (so a generational GC will not help).
>>>
>>> Perhaps the racket code is not “equivalent”. What is the total run time of the racket code compared to Gambit? Generational GC may reduce the time to do garbage collection, but slow down other operations (such as assignments).
>>>
>>> Concerning the parallel GC, there is a good 2x performance boost for a heap that contains a list of 10 million u8vectors of length 10 (see attached code):
>>>
>>> Without the parallel GC the pause time per GC:
>>> (real-time . .48944687843322754)
>>> (real-time . .35641002655029297)
>>> (real-time . .3395528793334961)
>>>
>>> With the parallel GC (./configure --enable-multiple-threaded-vms) the pause time per GC:
>>> (real-time . .23423385620117188)
>>> (real-time . .17566204071044922)
>>> (real-time . .1841750144958496)
>>>
>>> Marc
>>>
>>>
>>> (declare (standard-bindings) (extended-bindings) (not safe))
>>>
>>> (define obj
>>> (let loop ((i 10000000) (result '()))
>>> (if (fx> i 0)
>>> (loop (fx- i 1)
>>> (let ((vect (make-u8vector 10)))
>>> (cons vect
>>> result)))
>>> result)))
>>>
>>> (pp (assoc 'real-time (##exec-stats ##gc)))
>>> (pp (assoc 'real-time (##exec-stats ##gc)))
>>> (pp (assoc 'real-time (##exec-stats ##gc)))
>>>
>>>
>>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.iro.umontreal.ca/pipermail/gambit-list/attachments/20191110/aedec410/attachment.htm>


More information about the Gambit-list mailing list