Home.... | log in.... | Pub my question! | Sign-up....
Java-index >> Java HotSpot Virtual Machine >> Specifications

huge memory ramp up in two successive scavenge cycles

It's a web application for internal use.

J2SE 1.4.2_14

MEM_ARGS=" -Xms2028m -Xmx2028m -XX:PermSize=310m -XX:MaxPermSize=310m -XX:+UseConcMarkSweepGC -XX:+UseParNewGC \

-XX:NewSize=64M -XX:MaxNewSize=64M -XX:+CMSParallelRemarkEnabled -XX:ParallelGCThreads=2 -XX:SurvivorRatio=6 \

-verbose:gc -Xloggc:${GC_LOG} -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC"

GC_LOG:

30263.967: [GC {Heap before GC invocations=1592:

Heap

par new generationtotal 57344K, used 22279K [0x66c00000, 0x6ac00000, 0x6ac00000)

eden space 49152K, 28% used [0x66c00000, 0x679c1da0, 0x69c00000)

from space 8192K, 100% used [0x69c00000, 0x6a400000, 0x6a400000)

tospace 8192K,0% used [0x6a400000, 0x6a400000, 0x6ac00000)

concurrent mark-sweep generation total 2031616K, used 1499418K [0x6ac00000, 0xe6c00000, 0xe6c00000)

concurrent-mark-sweep perm gen total 307200K, used 276429K [0xe6c00000, 0xf9800000, 0xf9800000)

30263.967: [ParNew: 22279K->3192K(57344K), 30.0028214 secs]30293.970: [CMS (concurrent mode failure): 1507043K->1045599K(2031616K), 78.8167675 secs] 1521698K->1045599K(2088960K) Heap after GC invocations=1593:

Heap

par new generationtotal 57344K, used 0K [0x66c00000, 0x6ac00000, 0x6ac00000)

eden space 49152K,0% used [0x66c00000, 0x66c00000, 0x69c00000)

from space 8192K,0% used [0x6a400000, 0x6a400000, 0x6ac00000)

tospace 8192K,0% used [0x69c00000, 0x69c00000, 0x6a400000)

concurrent mark-sweep generation total 2031616K, used 1045599K [0x6ac00000, 0xe6c00000, 0xe6c00000)

concurrent-mark-sweep perm gen total 307200K, used 274064K [0xe6c00000, 0xf9800000, 0xf9800000)

} , 108.8201896 secs]

30381.915: [GC {Heap before GC invocations=1593:

Heap

par new generationtotal 57344K, used 49152K [0x66c00000, 0x6ac00000, 0x6ac00000)

eden space 49152K, 100% used [0x66c00000, 0x69c00000, 0x69c00000)

from space 8192K,0% used [0x6a400000, 0x6a400000, 0x6ac00000)

tospace 8192K,0% used [0x69c00000, 0x69c00000, 0x6a400000)

concurrent mark-sweep generation total 2031616K, used1412884K [0x6ac00000, 0xe6c00000, 0xe6c00000)

concurrent-mark-sweep perm gen total 307200K, used 274086K [0xe6c00000, 0xf9800000, 0xf9800000)

30381.915: [ParNew: 49152K->8192K(57344K), 54.6565942 secs] 1462036K->1422174K(2088960K) Heap after GC invocations=1594:

Heap

par new generationtotal 57344K, used 8192K [0x66c00000, 0x6ac00000, 0x6ac00000)

eden space 49152K,0% used [0x66c00000, 0x66c00000, 0x69c00000)

from space 8192K, 100% used [0x69c00000, 0x6a400000, 0x6a400000)

tospace 8192K,0% used [0x6a400000, 0x6a400000, 0x6ac00000)

concurrent mark-sweep generation total 2031616K, used 1413982K [0x6ac00000, 0xe6c00000, 0xe6c00000)

concurrent-mark-sweep perm gen total 307200K, used 274086K [0xe6c00000, 0xf9800000, 0xf9800000)

} , 54.6571394 secs]

Heap dump analysis:

We found two huge int arrays in heap, without parents and children. Each in 376M, no clue where they came from.

[3162 byte] By [flyingducka] at [2007-11-27 6:48:24]
«« Change DB's path
»» Aligning Text in Center of JOptionPane
# 1

Who can help to explain the sudden 370M allocation in old gen? Is it related to the 375M orphan int array in the heap dump? This looks so weird to me. I'm not sure if the concurrent mode failure left a garbage in heap, after all, the new size is only 64M, how come the huge 370M happened?

T.I.A.

flyingducka at 2007-7-12 18:21:47 > top of Java-index,Java HotSpot Virtual Machine,Specifications...
# 2

Here's a description of what's happening for the log snippet between the lines:

30263.967: [GC {Heap before GC invocations=1592:

... to ...

} , 108.8201896 secs]

At the start, the young gen is not quite half full with ~22M used out of ~57M. A large allocation request is made; there's not enough free space in the young gen, so a young collection is done. After the young collection, there's still not enough space in the young gen because the allocation size turns out to be larger than the entire young gen. So the JVM attempts to allocate in the old gen, which has enough total free space, but there isn't a single contiguous block of free space big enough to hold the allocation. So we do a mark-compact of the entire heap (indicated by the "concurrent mode failure"). After the mark-compact completes, the large object (~358M) is allocated in the old gen.

The only really surprising thing about this is that it took 30 seconds to do the young collection and 78 seconds for the mark-compact. Times that long usually indicate that the heap is being paged out, which should be avoided (keep the maximum heap size smaller than the available memory).

The next snippet of the log between the lines:

30381.915: [GC {Heap before GC invocations=1593:

...

} , 54.6571394 secs]

just shows that about 10 seconds later the young generation has filled up and a young GC is done.

You seem surprised that a 358M object is being allocated, but that's almost certainly what's happening. It may something done indirectly, in a library.

jxca at 2007-7-12 18:21:47 > top of Java-index,Java HotSpot Virtual Machine,Specifications...
Java HotSpot Virtual Machine
Specifications

Java HotSpot Virtual Machine Hot Topic

Java HotSpot Virtual Machine

All Classified