[racket] racket http server, major GC: -216 bytes collected

I don't quite understand if you're showing us the full output or if
we're seeing something that's abridged somehow (I thought you were
saying that we're seeing only one line for every 20 seconds, but that
would mean that the webserver took several minutes to start up which
doesn't seem right) but, in any case, that pattern of memory use would
indicate to me that nothing is wrong. Specifically, the memory total
is not growing (beyond some epsilons that don't mean much).

Am I misreading something somehow?

Robby

On Tue, Jan 11, 2011 at 4:20 PM, Stefan Schmiedl <s at xss.de> wrote:
> Dear readers,
>
> I have some more experimental data on this issue.
>
> On Mon, 10 Jan 2011 18:00:35 +0100
> Stefan Schmiedl <s at xss.de> wrote:
>
>> On Mon, 10 Jan 2011 06:53:36 -0700
>> Matthew Flatt <mflatt at cs.utah.edu> wrote:
>>
>> > Meanwhile, I'm not sure why you're seeing GCs at all when the server is
>> > idle. The GCs unexpected, right? But if you're using the LRU manager,
>> > it seems to call `collect-garbage' along with its collection routine.
>>
>> ... except having around the LRU manager. Good point. I'll try using
>> another manager and see if it makes a difference. But right now it looks
>> as if the act of GC is causing a tiny leak.
>
> It seems to be the LRU manager, as the following (gctest7.rkt) indicates:
>
>  #lang racket
>
>  (require web-server/web-server
>           web-server/servlet-dispatch
>           web-server/managers/lru)
>
>  (serve
>   #:dispatch (dispatch/servlet
>               (lambda (request) '(html (head (title "hello world")) (body "hello world")))
>               #:manager (create-LRU-manager
>                          ;; Called when an instance has expired.
>                          #f
>                          ;; The condition below is checked every 20 seconds
>                          20
>                          ;; One 'life point' is deducted every 10 minutes
>                          600
>                          ;; If this condition is true a 'life point' is deducted
>                          ;; from the continuation
>                          (lambda () #t)
>                          ;; The number of 'life points' an continuation starts with
>                          #:initial-count 4
>                          ;; Logging done whenever an continuation is collected
>                          #:inform-p (lambda args (void))))
>   #:port 8080)
>
>  (define (loop)
>    (collect-garbage)
>    (sleep 2)
>    (loop))
>
>  (thread loop)
>  (read-line)
>
> Checking every 20 seconds gives the following pattern with a GC forced at 2 seconds:
>
>  stefan at g128 racket % ~/racket/bin/racket -W debug gctest7.rkt
>  GC [minor] at 1485080 bytes; 647736 collected in 2 msec
>  GC [minor] at 2132912 bytes; 647104 collected in 1 msec
>  GC [minor] at 4266336 bytes; 1335376 collected in 2 msec
>  GC [minor] at 5496832 bytes; 1236464 collected in 4 msec
>  GC [minor] at 7322056 bytes; 987600 collected in 5 msec
>  GC [minor] at 11401128 bytes; 2517656 collected in 7 msec
>  GC [minor] at 15155408 bytes; 3241472 collected in 12 msec
>  GC [minor] at 19746560 bytes; 3983888 collected in 14 msec
>  GC [minor] at 25194528 bytes; 4238080 collected in 16 msec
>  GC [minor] at 32454320 bytes; 6018064 collected in 15 msec
>  GC [minor] at 41958720 bytes; 8058944 collected in 25 msec
>  GC [minor] at 53566320 bytes; 11580760 collected in 39 msec
>  #<procedure:...-server-unit.rkt:46:2>
>  #<thread:loop>
>  GC [major] at 58657600 bytes; 16634104 collected in 71 msec
>  GC [major] at 42060360 bytes; 3611240 collected in 66 msec
>  GC [major] at 38449120 bytes; 0 collected in 60 msec
>  GC [major] at 38449120 bytes; 4176 collected in 60 msec
>  GC [major] at 38444944 bytes; 0 collected in 61 msec
>  GC [major] at 38444944 bytes; 0 collected in 60 msec
>  GC [major] at 38444944 bytes; 0 collected in 61 msec
>  GC [major] at 38444944 bytes; 0 collected in 61 msec
>  GC [major] at 38444944 bytes; 0 collected in 60 msec
>  GC [major] at 38444944 bytes; 0 collected in 60 msec
>  GC [major] at 38444944 bytes; -9768 collected in 60 msec
>  GC [major] at 38454712 bytes; 0 collected in 61 msec
>  GC [major] at 38454712 bytes; 0 collected in 61 msec
>  GC [major] at 38454712 bytes; 0 collected in 60 msec
>  GC [major] at 38454712 bytes; 0 collected in 60 msec
>  GC [major] at 38454712 bytes; 0 collected in 60 msec
>  GC [major] at 38454712 bytes; 0 collected in 61 msec
>  GC [major] at 38454712 bytes; 0 collected in 60 msec
>  GC [major] at 38454712 bytes; 0 collected in 60 msec
>  GC [major] at 38454712 bytes; 0 collected in 60 msec
>  GC [major] at 38454712 bytes; -3800 collected in 60 msec
>  GC [major] at 38458512 bytes; 0 collected in 60 msec
>  GC [major] at 38458512 bytes; 0 collected in 60 msec
>  GC [major] at 38458512 bytes; 0 collected in 60 msec
>  GC [major] at 38458512 bytes; 0 collected in 60 msec
>  GC [major] at 38458512 bytes; 0 collected in 60 msec
>  GC [major] at 38458512 bytes; 0 collected in 62 msec
>  GC [major] at 38458512 bytes; 0 collected in 60 msec
>  GC [major] at 38458512 bytes; 0 collected in 60 msec
>  GC [major] at 38458512 bytes; 0 collected in 61 msec
>  GC [major] at 38458512 bytes; -2984 collected in 61 msec
>  GC [major] at 38461496 bytes; 0 collected in 60 msec
>  GC [major] at 38461496 bytes; 0 collected in 61 msec
>  GC [major] at 38461496 bytes; 0 collected in 60 msec
>  GC [major] at 38461496 bytes; 0 collected in 61 msec
>  GC [major] at 38461496 bytes; 0 collected in 60 msec
>  GC [major] at 38461496 bytes; 0 collected in 60 msec
>  GC [major] at 38461496 bytes; 0 collected in 60 msec
>  GC [major] at 38461496 bytes; 0 collected in 60 msec
>  GC [major] at 38461496 bytes; -3144 collected in 63 msec
>  GC [major] at 38464640 bytes; 0 collected in 61 msec
>  GC [major] at 38464640 bytes; 0 collected in 61 msec
>  GC [major] at 38464640 bytes; 0 collected in 60 msec
>  GC [major] at 38464640 bytes; 0 collected in 60 msec
>  GC [major] at 38464640 bytes; 0 collected in 61 msec
>  GC [major] at 38464640 bytes; 0 collected in 60 msec
>  GC [major] at 38464640 bytes; 0 collected in 60 msec
>  GC [major] at 38464640 bytes; 0 collected in 60 msec
>  GC [major] at 38464640 bytes; 0 collected in 61 msec
>  GC [major] at 38464640 bytes; -1960 collected in 60 msec
>  GC [major] at 38466600 bytes; 0 collected in 60 msec
>  GC [major] at 38466600 bytes; 0 collected in 59 msec
>  GC [major] at 38466600 bytes; 0 collected in 60 msec
>  GC [major] at 38466600 bytes; 0 collected in 60 msec
>  GC [major] at 38466600 bytes; 0 collected in 60 msec
>  GC [major] at 38466600 bytes; 0 collected in 61 msec
>  GC [major] at 38466600 bytes; 0 collected in 61 msec
>  GC [major] at 38466600 bytes; 0 collected in 61 msec
>  GC [major] at 38466600 bytes; 0 collected in 62 msec
>  GC [major] at 38466600 bytes; -648 collected in 62 msec
>  GC [major] at 38467248 bytes; 0 collected in 60 msec
>  GC [major] at 38467248 bytes; 0 collected in 60 msec
>  GC [major] at 38467248 bytes; 0 collected in 60 msec
>  GC [major] at 38467248 bytes; 0 collected in 60 msec
>  GC [major] at 38467248 bytes; 0 collected in 60 msec
>  GC [major] at 38467248 bytes; 0 collected in 60 msec
>  GC [major] at 38467248 bytes; 0 collected in 62 msec
>  GC [major] at 38467248 bytes; 0 collected in 60 msec
>  GC [major] at 38467248 bytes; -648 collected in 61 msec
>  GC [major] at 38467896 bytes; 0 collected in 60 msec
>  GC [major] at 38467896 bytes; 0 collected in 61 msec
>  GC [major] at 38467896 bytes; 0 collected in 60 msec
>  GC [major] at 38467896 bytes; 0 collected in 60 msec
>  GC [major] at 38467896 bytes; 0 collected in 60 msec
>  GC [major] at 38467896 bytes; 0 collected in 60 msec
>  GC [major] at 38467896 bytes; 0 collected in 60 msec
>  GC [major] at 38467896 bytes; 0 collected in 62 msec
>  GC [major] at 38467896 bytes; 0 collected in 60 msec
>  GC [major] at 38467896 bytes; -648 collected in 61 msec
>  GC [major] at 38468544 bytes; 0 collected in 61 msec
>  GC [major] at 38468544 bytes; 0 collected in 61 msec
>  GC [major] at 38468544 bytes; 0 collected in 60 msec
>  GC [major] at 38468544 bytes; 0 collected in 60 msec
>  GC [major] at 38468544 bytes; 0 collected in 60 msec
>
> I'd say that this is strongly indicates that something inside the LRU manager
> is hoarding RAM. I'm still not sending requests to the server.
>
> BTW, I'm getting these results on the follwing 64-bit linux system
>  Linux g128 2.6.34-gentoo-r1-1020 #5 SMP Wed Oct 20 00:28:02 CEST 2010 x86_64 Intel(R) Core(TM)2 Duo CPU E8500 @ 3.16GHz GenuineIntel GNU/Linux
> running racket fresh from git (v5.0.99.6).
>
> Looking at what's going on inside the LRU manager, I have to admit that
> I'm a bit out of my depth there.
>
> Am I still chasing ghosts or is there something going on?
>
> Curious,
> s.
>