[Gc] RE: GC_gcollect and memory usage increase

Boehm, Hans hans.boehm at hp.com
Mon Nov 20 17:05:26 PST 2006


So it sounds like the log that's being generated is the interleaved log
from the two processes?  The resolves some mysteries.

The log file is opened around line 880 in misc.c.  If you concatenate
something to the file name that varies in the two processes, you should
be able to separate the logs form the two processes.  With luck, that
will make it far clearer what is happening.

Hans

> -----Original Message-----
> From: Simon Tsai [mailto:mtsai at adobe.com] 
> Sent: Sunday, November 19, 2006 10:15 PM
> To: Boehm, Hans
> Cc: gc at napali.hpl.hp.com
> Subject: RE: GC_gcollect and memory usage increase
> 
> My program is written in c++ and muti-thread. I have added 
> gc_cpp.cpp in my application. I remove the gc_cpp.cpp from 
> gc.dll. My application launch two processes - the same 
> program, one process is not doing much, the other one is 
> active. I set breakpoint for checking GC_gc_no. I saw 
> GC_gc_no have two different values. Will each process has its 
> own gc.dll or share the same gc.dll? If it shares the same 
> gc.dll, it could cause problems.
> 
> Thanks,
> 
> simon 
> 
> -----Original Message-----
> From: Boehm, Hans [mailto:hans.boehm at hp.com]
> Sent: Friday, November 17, 2006 5:10 PM
> To: Simon Tsai
> Cc: gc at napali.hpl.hp.com; gc at napali.hpl.hp.com
> Subject: RE: GC_gcollect and memory usage increase
> 
> Repeated memory growth like this may occur if a lot of the 
> heap is "blacklisted" because the collector saw what appeared 
> to be pointers into the newly allocated heap sections, and is 
> trying to find a way to allocate around such known bogus 
> pointers.  But based on the logs you attached, things go 
> fairly badly wrong well before that.
> 
> Was the collector built completely according to one of the recipes in
> README.win32 for the multithreaded collector?  If so, I would 
> set a breakpoint at the "Marking for collection" printf in 
> GC_stopped_mark in alloc.c, and check whether GC_gc_no is 
> really decreasing between messages, or whether the two 
> messages are coming from different copies of the collector 
> that were linked in by mistake somehow.  If GC_gc_no is 
> really decreasing, a watchpoint on it should be informative.
> 
> Hans
> 
> > -----Original Message-----
> > From: Simon Tsai [mailto:mtsai at adobe.com]
> > Sent: Friday, November 17, 2006 10:05 AM
> > To: Boehm, Hans
> > Cc: gc at napali.hpl.hp.com; gc at napali.hpl.hp.com
> > Subject: GC_gcollect and memory usage increase
> > 
> > 
> > 
> > My program is a muti-threaded server. It has more than 20 threads 
> > running. Every time when my program call GC_gcollect(), I 
> saw memory 
> > usage increase. After program allocate more than 200 Mbytes memory, 
> > each time GC_gcollect() get called, the memory usage start to jump.
> > Eventually, my system runs out of memory. Does anyone see this 
> > problem?
> > Any ways to prevent this happen?
> > 
> > From gc.log:
> > 
> > Immediately reclaimed -149556 bytes in heap of size 1099886592 bytes
> > 580907008 (atomic) + 31759328 (composite) collectable bytes in use 
> > Finalize + initiate sweep took 0 + 688 msecs Complete 
> collection took 
> > 12937 msecs Increasing heap size by 16777216 after 124532 allocated 
> > bytes Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes
> > 
> > Why it keeps allocating 16 Mbytes memory, even my program did not 
> > request so much memory? Is this a bug?
> > Why collection took 12937 msecs? It's a long time. 
> > 
> > Thanks,
> > 
> > 
> > Simon
> > 
> > 
> > =========================== gc.log ==========
> > 
> > --> Marking for collection 7 after 214900 allocd bytes + 0
> > wasted bytes
> > Collection 6 reclaimed 0 bytes ---> heapsize = 1433600 bytes 
> > World-stopped marking took 1203 msecs Bytes recovered 
> before sweep - 
> > f.l. count = -20164 Immediately reclaimed -20164 bytes in 
> heap of size 
> > 1433600 bytes 0 (atomic) + 118052
> > (composite) collectable bytes in use Finalize + initiate 
> sweep took 0 
> > + 0 msecs Complete collection took 1719 msecs interior pointers
> > --> Marking for collection 5 after 219478292 allocd bytes + 28187368
> > wasted bytes
> > Found new system malloc AllocationBase at 0x6ff0000 GC
> > Warning: Thread stack pointer 0x5effe60 out of range, pushing 
> > everything Collection 4 reclaimed 328 bytes ---> heapsize = 
> 227471360 
> > bytes World-stopped marking took 7594 msecs Bytes recovered before 
> > sweep - f.l. count = -132976 Immediately reclaimed -132976 bytes in 
> > heap of size 227471360 bytes 0
> > (atomic) + 17152084 (composite) collectable bytes in use Finalize + 
> > initiate sweep took 0 + 15 msecs Complete collection took 
> 10109 msecs 
> > Increasing heap size by 16777216 after 1594276 allocated bytes 
> > Increasing heap size by
> > 16777216 after 1594276 allocated bytes Increasing heap size by 
> > 16777216 after 1775784 allocated bytes Increasing heap size by 
> > 16777216 after 1775784 allocated bytes Increasing heap size by 
> > 16777216 after 1775784 allocated bytes Increasing heap size by 
> > 16777216 after 2001608 allocated bytes Increasing heap size by 
> > 16777216 after 2001608 allocated bytes Increasing heap size by 
> > 16777216 after
> > 2049756 allocated bytes Increasing heap size by 16777216 
> after 2049756 
> > allocated bytes Increasing heap size by
> > 16777216 after 15754676 allocated bytes Increasing heap size by 
> > 16777216 after 34413680 allocated bytes Increasing heap size by 
> > 16777216 after 52047912 allocated bytes Increasing heap size by 
> > 16777216 after 69681988 allocated bytes Increasing heap size by 
> > 16777216 after 86951164 allocated bytes Increasing heap size by 
> > 16777216 after 104327052 allocated bytes Increasing heap size by 
> > 16777216 after
> > 121389896 allocated bytes Initiating full world-stop collection 6 
> > after 122212480 allocd bytes
> > 151089152 bytes in heap blacklisted for interior pointers
> > --> Marking for collection 6 after 122212480 allocd bytes + 
> 145697160
> > wasted bytes
> > GC Warning: Thread stack pointer 0x5effe60 out of range, pushing 
> > everything Collection 5 reclaimed 709040 bytes ---> heapsize = 
> > 495906816 bytes World-stopped marking took 6313 msecs Bytes 
> recovered 
> > before sweep - f.l. count = -162576 Immediately reclaimed -162576 
> > bytes in heap of size 495906816 bytes 132382720 (atomic) + 26088876 
> > (composite) collectable bytes in use Finalize + initiate 
> sweep took 0 
> > + 15 msecs Complete collection took 6562 msecs Increasing 
> heap size by
> > 16777216 after 935676 allocated bytes Increasing heap size by
> > 16777216 after 935676 allocated bytes Increasing heap size by
> > 16777216 after 935676 allocated bytes Increasing heap size by
> > 16777216 after 935676 allocated bytes Increasing heap size by
> > 16777216 after 935676 allocated bytes Increasing heap size by
> > 16777216 after 935676 allocated bytes Increasing heap size by
> > 16777216 after 935676 allocated bytes Increasing heap size by
> > 16777216 after 935676 allocated bytes Increasing heap size by
> > 16777216 after 935676 allocated bytes Increasing heap size by
> > 16777216 after 935676 allocated bytes Increasing heap size by
> > 16777216 after 935676 allocated bytes Increasing heap size by
> > 16777216 after 935676 allocated bytes Increasing heap size by
> > 16777216 after 935676 allocated bytes Increasing heap size by
> > 16777216 after 20956028 allocated bytes Increasing heap size by 
> > 16777216 after 39119576 allocated bytes Increasing heap size by 
> > 16777216 after 57230224 allocated bytes Initiating full world-stop 
> > collection 7 after 64250476 allocd bytes 238878720 bytes in heap 
> > blacklisted for interior pointers
> > --> Marking for collection 7 after 64250476 allocd bytes + 224500120
> > wasted bytes
> > Found new system malloc AllocationBase at 0x7c50000 GC
> > Warning: Thread stack pointer 0x5effe60 out of range, pushing 
> > everything Collection 6 reclaimed 512912 bytes ---> heapsize = 
> > 764342272 bytes World-stopped marking took 20219 msecs 
> Bytes recovered 
> > before sweep - f.l. count = -191728 Immediately reclaimed -191728 
> > bytes in heap of size 764342272 bytes 352849920 (atomic) + 29610156 
> > (composite) collectable bytes in use Finalize + initiate 
> sweep took 0 
> > + 1594 msecs Complete collection took 23297 msecs 
> Increasing heap size 
> > by
> > 16777216 after 68380 allocated bytes Increasing heap size by
> > 16777216 after 68380 allocated bytes Increasing heap size by
> > 16777216 after 68380 allocated bytes Increasing heap size by
> > 16777216 after 68380 allocated bytes Increasing heap size by
> > 16777216 after 68380 allocated bytes Increasing heap size by
> > 16777216 after 68380 allocated bytes Increasing heap size by
> > 16777216 after 68380 allocated bytes Increasing heap size by
> > 16777216 after 68380 allocated bytes Increasing heap size by
> > 16777216 after 68380 allocated bytes Increasing heap size by
> > 16777216 after 288544 allocated bytes Increasing heap size by
> > 16777216 after 288544 allocated bytes Increasing heap size by
> > 16777216 after 311252 allocated bytes Increasing heap size by
> > 16777216 after 311252 allocated bytes Increasing heap size by
> > 16777216 after 311252 allocated bytes Increasing heap size by
> > 16777216 after 311252 allocated bytes Increasing heap size by
> > 16777216 after 311252 allocated bytes Increasing heap size by
> > 16777216 after 311252 allocated bytes Increasing heap size by
> > 16777216 after 9812544 allocated bytes Increasing heap size by 
> > 16777216 after 27763888 allocated bytes Increasing heap size by 
> > 16777216 after 45117616 allocated bytes Initiating full world-stop 
> > collection 8 after 48860960 allocd bytes
> > 307335168 bytes in heap blacklisted for interior pointers
> > --> Marking for collection 8 after 48860960 allocd bytes + 231524464
> > wasted bytes
> > Found new system malloc AllocationBase at 0x6100000 GC
> > Warning: Thread stack pointer 0x5effe60 out of range, pushing 
> > everything Collection 7 reclaimed 517728 bytes ---> heapsize = 
> > 1099886592 bytes World-stopped marking took 8281 msecs 
> Bytes recovered 
> > before sweep - f.l. count = -149556 Immediately reclaimed -149556 
> > bytes in heap of size 1099886592 bytes
> > 580907008 (atomic) + 31759328 (composite) collectable bytes in use 
> > Finalize + initiate sweep took 0 + 688 msecs Complete 
> collection took 
> > 12937 msecs Increasing heap size by 16777216 after 124532 allocated 
> > bytes Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes 
> > Increasing heap size by 16777216 after 124532 allocated bytes 
> > Initiating full world-stop collection 9 after 4770548 allocd bytes
> > 403144704 bytes in heap blacklisted for interior pointers
> > --> Marking for collection 9 after 4770548 allocd bytes + 
> 75780 wasted
> > bytes
> > 
> 



More information about the Gc mailing list