[erlang-questions] Extraordinarily long garbage collection with R12B-2

[David Lutz]

A follow up with a bit more info below.

D.L.


On Jun 29, 2008, at 7:11 PM, David Lutz wrote:

> I am still pretty much an erlang newbie, so hopefully I am missing
> something obvious.
>
> We have an program that was running OK with R11B-4, but now is
> experiencing incredibly long garbage collection times under load with
> R12B-2.  The application is serving network requests, many clients
> connecting only for a short period, request/response style.  We have
> erlang:system_monitor/2 set up to deliver messages if GC takes more
> than 1000ms.  With R11B-4 we almost never saw this.  With R12B-2 it
> happens fairly regularly and the timeouts are really long, most of the
> reports are for timeout of 4294967.  Occasionally a slightly smaller
> timeout will be reported, but always well over 4000000.  The long GC
> happens in both our long running gen_server processes and our
> ephemeral worker processes.  Obviously our clients experience timeouts
> and other connection errors while this long GC is happening.

OK, after a further research, it turns out that our client issues were  
caused by a different problem.  In fact it would appear that these  
long_gc messages are completely spurious.  I see no evidence that any  
GC took any appreciable amount of time.  One thing that I noticed a  
bit later is the timeout value is (2^32)/1000 on our 32bit hosts,  
however we are getting the same reports on our 64bit hosts with a  
timeout value of (2^64)/1000.  This looks suspiciously like a counter/ 
timer in the VM is having rollover issues.


> Below is small clip from our log file showing the long GC reports.
> Has anybody seen this issue before?  Why would R12B-2 behave so much
> different that R11B-4 in this respect?  What steps can I try to
> pinpoint the issue?
>
> Thanks,
> D.L.
>
> =INFO REPORT==== 2008-06-29 02:02:41 UTC ===
> Long GC in <0.13094.0>: [{timeout,4294967},
>                          {old_heap_block_size,610},
>                          {heap_block_size,987},
>                          {mbuf_size,0},
>                          {stack_size,10},
>                          {old_heap_size,173},
>                          {heap_size,425}]
> ProcessRegisteredName: []
>
> =INFO REPORT==== 2008-06-29 02:02:43 UTC ===
> Long GC in <0.59.0>: [{timeout,4295024},
>                       {old_heap_block_size,377},
>                       {heap_block_size,610},
>                       {mbuf_size,0},
>                       {stack_size,26},
>                       {old_heap_size,118},
>                       {heap_size,7}]
> ProcessRegisteredName: {registered_name,XXX}