help me to analyz GC log

[Jessica White]

I used the following setting to start my Java application on Windows XP machine which has duo-core CPU.

-Xms128m -Xmx256m

The following is part of the gc log:

23216.560: [GC 23216.560: [DefNew: 8950K->715K(9216K), 0.0056082 secs] 125543K->117994K(130240K), 0.0056901 secs]
23217.722: [GC 23217.722: [DefNew: 8971K->602K(9216K), 0.0039623 secs] 126250K->118282K(130240K), 0.0040495 secs]
23219.905: [GC 23219.905: [DefNew: 8858K->689K(9216K), 0.0034197 secs] 126538K->118475K(130240K), 0.0035068 secs]
23220.031: [GC 23220.031: [DefNew: 8945K->619K(9216K), 0.0029327 secs] 126731K->118467K(130240K), 0.0030200 secs]
23229.378: [GC 23229.378: [DefNew: 8875K->557K(9216K), 0.0044134 secs] 126723K->119003K(130240K), 0.0045044 secs]
23243.886: [GC 23243.886: [DefNew: 8813K->567K(9216K), 0.0042516 secs] 127259K->119517K(130240K), 0.0043398 secs]
23266.633: [GC 23266.633: [DefNew: 8823K->279K(9216K), 0.0036507 secs] 127773K->119732K(130240K), 0.0037580 secs]
23267.872: [GC 23267.872: [DefNew: 8535K->960K(9216K), 0.0044051 secs] 127988K->120603K(130240K), 0.0044819 secs]
23270.088: [GC 23270.088: [DefNew: 9216K->784K(9216K), 0.0041400 secs] 128859K->120679K(130240K), 0.0042216 secs]
23278.476: [GC 23278.476: [DefNew: 9040K->631K(9216K), 0.0044097 secs] 128935K->120993K(130240K), 0.0045021 secs]
23278.688: [GC 23278.688: [DefNew: 8887K->908K(9216K), 0.0044983 secs] 129249K->121525K(130240K), 0.0045866 secs]
23281.930: [GC 23281.930: [DefNew: 9164K->785K(9216K), 0.0041566 secs] 129781K->121706K(130240K), 0.0042425 secs]
23283.140: [GC 23283.141: [DefNew: 9041K->737K(9216K), 0.0050692 secs]23283.146: [Tenured: 121386K->32243K(121408K), 0.1399366 secs] 129962K->32243K(130624K), 0.1452084 secs]
23285.531: [GC 23285.531: [DefNew: 8256K->960K(9216K), 0.0039761 secs] 40499K->33243K(130240K), 0.0040601 secs]
23285.692: [GC 23285.692: [DefNew: 9216K->891K(9216K), 0.0044289 secs] 41499K->33537K(130240K), 0.0045118 secs]
23286.905: [GC 23286.905: [DefNew: 9147K->703K(9216K), 0.0038890 secs] 41793K->33690K(130240K), 0.0039799 secs]
23289.136: [GC 23289.136: [DefNew: 8959K->819K(9216K), 0.0041377 secs] 41946K->34034K(130240K), 0.0042251 secs]
23289.341: [GC 23289.341: [DefNew: 9075K->948K(9216K), 0.0044032 secs] 42290K->34445K(130240K), 0.0044979 secs]
23307.070: [GC 23307.070: [DefNew: 9204K->392K(9216K), 0.0049331 secs] 42701K->34827K(130240K), 0.0050170 secs]
23309.251: [GC 23309.251: [DefNew: 8648K->960K(9216K), 0.0038198 secs] 43083K->35467K(130240K), 0.0039015 secs]
23310.402: [GC 23310.402: [DefNew: 9216K->680K(9216K), 0.0051652 secs] 43723K->36021K(130240K), 0.0052474 secs]
23310.521: [GC 23310.521: [DefNew: 8936K->720K(9216K), 0.0031669 secs] 44277K->36143K(130240K), 0.0032542 secs]


It looks like minor GC happens very frequently, every 1-2 seconds. I also did statistics on major GC collection, it happens about every 800 seconds.

Upon terminating the application, I have the following at the end of my gc log file:

Heap
def new generation total 9216K, used 3705K [0x16990000, 0x17380000, 0x17d40000)
eden space 8256K, 43% used [0x16990000, 0x16d1c1e8, 0x171a0000)
from space 960K, 7% used [0x171a0000, 0x171b24a8, 0x17290000)
to space 960K, 0% used [0x17290000, 0x17290000, 0x17380000)
tenured generation total 121024K, used 103325K [0x17d40000, 0x1f370000, 0x26990000)
the space 121024K, 85% used [0x17d40000, 0x1e227718, 0x1e227800, 0x1f370000)
compacting perm gen total 12288K, used 3172K [0x26990000, 0x27590000, 0x2a990000)
the space 12288K, 25% used [0x26990000, 0x26ca9278, 0x26ca9400, 0x27590000)
ro space 8192K, 62% used [0x2a990000, 0x2ae8e4e8, 0x2ae8e600, 0x2b190000)
rw space 12288K, 52% used [0x2b190000, 0x2b7d0e78, 0x2b7d1000, 0x2bd90000)

It is a charting software with script execution capability. I am having Outofmemory problem when having too many charts open or with too many scripts running. The above log was captured with a low load testing.

Anybody would have any suggestion based on the log?
Does the minor GC happen too frequently?
Would I benefit by using Concurrent Low Pause Collector instead of serial collector on such duo-core CPU chip? Somebody told me such CPU can not be considered real 2-CPU. So I am hesitant to go that route.

I am going to run medium-high load testing on a better machine to produce more gc logs.

Thank you for any input as I am really new on resolving java memory issues.

[raj vin]

Try Xms128m -Xmx512m and compare the logs.