• Post Reply Bookmark Topic Watch Topic
  • New Topic
programming forums Java Mobile Certification Databases Caching Books Engineering Micro Controllers OS Languages Paradigms IDEs Build Tools Frameworks Application Servers Open Source This Site Careers Other Pie Elite all forums
this forum made possible by our volunteer staff, including ...
Marshals:
  • Campbell Ritchie
  • Jeanne Boyarsky
  • Ron McLeod
  • Paul Clapham
  • Liutauras Vilda
Sheriffs:
  • paul wheaton
  • Rob Spoor
  • Devaka Cooray
Saloon Keepers:
  • Stephan van Hulst
  • Tim Holloway
  • Carey Brown
  • Frits Walraven
  • Tim Moores
Bartenders:
  • Mikalai Zaikin

help me to analyz GC log

 
Ranch Hand
Posts: 30
  • Mark post as helpful
  • send pies
    Number of slices to send:
    Optional 'thank-you' note:
  • Quote
  • Report post to moderator
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.
 
Greenhorn
Posts: 12
  • Mark post as helpful
  • send pies
    Number of slices to send:
    Optional 'thank-you' note:
  • Quote
  • Report post to moderator
Try Xms128m -Xmx512m and compare the logs.
 
With a little knowledge, a cast iron skillet is non-stick and lasts a lifetime.
reply
    Bookmark Topic Watch Topic
  • New Topic