File APIs for Java Developers
Manipulate DOC, XLS, PPT, PDF and many others from your application.
The moose likes Performance and the fly likes help me to analyz GC log Big Moose Saloon
  Search | Java FAQ | Recent Topics | Flagged Topics | Hot Topics | Zero Replies
Register / Login
JavaRanch » Java Forums » Java » Performance
Bookmark "help me to analyz GC log" Watch "help me to analyz GC log" New topic

help me to analyz GC log

Jessica White
Ranch Hand

Joined: Sep 24, 2004
Posts: 30
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:

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

Joined: Mar 17, 2007
Posts: 12
Try Xms128m -Xmx512m and compare the logs.
I agree. Here's the link:
subject: help me to analyz GC log