wood burning stoves 2.0*
The moose likes Performance and the fly likes Understanding the each line in GC logs Big Moose Saloon
  Search | Java FAQ | Recent Topics | Flagged Topics | Hot Topics | Zero Replies
Register / Login


Win a copy of The Java EE 7 Tutorial Volume 1 or Volume 2 this week in the Java EE forum
or jQuery UI in Action in the JavaScript forum!
JavaRanch » Java Forums » Java » Performance
Bookmark "Understanding the each line in GC logs" Watch "Understanding the each line in GC logs" New topic
Author

Understanding the each line in GC logs

trupti nigam
Ranch Hand

Joined: Jun 21, 2001
Posts: 613
Can some one please explain What each segment represents in the below GS logs.

2012-03-16T21:50:02.051-0400: 1.453: [GC 1.453:

I know that :
2012-03-16 is Date

T21:50:02 is Time

What are these numbers.?.051-0400

1.453: is Seconds elapsed from JVm start.

GC 1.453 What does the number 1.453 represent?

===>

Also I see below lines..

2012-03-16T21:50:02.051-0400: 1.453: [GC 1.453: [DefNew: 17024K->1479K(19136K), 0.0306320 secs] 17024K->1479K(4716480K), 0.0307612 secs] [Times: user=0.03 sys=0.00, real=0.03 secs]
2012-03-16T21:50:02.738-0400: 2.140: [GC 2.140: [DefNew: 18503K->1399K(19136K), 0.0313482 secs] 18503K->2867K(4716480K), 0.0316311 secs] [Times: user=0.03 sys=0.00, real=0.03 secs]
2012-03-16T21:50:36.295-0400: 35.716: [GC 35.716: [DefNew: 17463K->2112K(19136K), 0.0365011 secs] 18931K->8790K(4716480K), 0.0366094 secs] [Times: user=0.03 sys=0.00, real=0.04 secs]
2012-03-16T21:50:38.576-0400: 37.999: [GC 37.999: [DefNew: 17929K->2112K(19136K), 0.0268604 secs] 24607K->13408K(4716480K), 0.0270167 secs] [Times: user=0.02 sys=0.00, real=0.03 secs]
2012-03-16T21:50:38.847-0400: 38.270: [GC 38.270: [DefNew: 19136K->2111K(19136K), 0.0310339 secs] 30432K->21629K(4716480K), 0.0312018 secs] [Times: user=0.03 sys=0.00, real=0.03 secs]
2012-03-16T21:50:39.097-0400: 38.521: [GC 38.521: [DefNew: 19135K->2111K(19136K), 0.0439560 secs] 38653K->32741K(4716480K), 0.0441413 secs] [Times: user=0.04 sys=0.01, real=0.04 secs]
2012-03-16T21:50:39.237-0400: 38.660: [GC 38.660: [DefNew: 19135K->2112K(19136K), 0.0406637 secs] 49765K->46744K(4716480K), 0.0408250 secs] [Times: user=0.03 sys=0.01, real=0.04 secs]
2012-03-16T21:50:39.386-0400: 38.809: [GC 38.809: [DefNew: 19136K->2112K(19136K), 0.0546626 secs] 63768K->58136K(4716480K), 0.0548196 secs] [Times: user=0.05 sys=0.01, real=0.05 secs]
2012-03-16T21:50:39.593-0400: 39.016: [GC 39.016: [DefNew: 18499K->2111K(19136K), 0.0674221 secs] 74523K->68151K(4716480K), 0.0675698 secs] [Times: user=0.06 sys=0.01, real=0.07 secs]
2012-03-16T21:50:39.742-0400: 39.166: [GC 39.166: [DefNew: 19135K->2112K(19136K), 0.0434530 secs] 85175K->80143K(4716480K), 0.0436007 secs] [Times: user=0.04 sys=0.01, real=0.04 secs]
2012-03-16T21:50:40.076-0400: 39.500: [GC 39.500: [DefNew: 19136K->2112K(19136K), 0.0494914 secs] 97167K->91600K(4716480K), 0.0496460 secs] [Times: user=0.04 sys=0.01, real=0.05 secs]
2012-03-16T21:50:40.315-0400: 39.739: [GC 39.739: [DefNew: 19136K->2112K(19136K), 0.0871744 secs] 108624K->102826K(4716480K), 0.0873283 secs] [Times: user=0.08 sys=0.01, real=0.09 secs]
2012-03-16T21:50:40.483-0400: 39.907: [GC 39.907: [DefNew: 19136K->2111K(19136K), 0.0537840 secs] 119850K->117478K(4716480K), 0.0539313 secs] [Times: user=0.05 sys=0.01, real=0.05 secs]
2012-03-16T21:50:40.676-0400: 40.100: [GC 40.100: [DefNew: 14032K->2111K(19136K), 0.0704367 secs] 129398K->125169K(4716480K), 0.0706485 secs] [Times: user=0.07 sys=0.01, real=0.07 secs]
2012-03-16T21:50:40.932-0400: 40.357: [GC 40.357: [DefNew: 19135K->2112K(19136K), 0.0560715 secs] 142193K->136424K(4716480K), 0.0562228 secs] [Times: user=0.05 sys=0.01, real=0.06 secs]
2012-03-16T21:50:41.061-0400: 40.486: [GC 40.486: [DefNew: 19136K->2112K(19136K), 0.0446807 secs] 153448K->150856K(4716480K), 0.0448455 secs] [Times: user=0.04 sys=0.01, real=0.04 secs]
2012-03-16T21:50:41.213-0400: 4

My understanding is each line represents the GC. There are multiple GC at 21.50 with few milli difference. IS my understanding correct? Is there a way that we can indicate in the GC params, so that the GC runs are reguar intervals?

thanks


fred rosenberger
lowercase baba
Bartender

Joined: Oct 02, 2003
Posts: 11255
    
  16

21:50:02.051-0400

is ALL the time. Hours, minutes, seconds, fraction of a second (51/1000) and then the GMT offset. This was done in a timezone four hours behind GMT.


There are only two hard things in computer science: cache invalidation, naming things, and off-by-one errors
Prabaharan Gopalan
Ranch Hand

Joined: Oct 16, 2009
Posts: 66

See if this is what you're looking for: http://java.sun.com/docs/hotspot/gc1.4.2/ section 2.2 Measurement

Googling doesn't make you a genius. But not Googling makes you dumber.
 
I agree. Here's the link: http://aspose.com/file-tools
 
subject: Understanding the each line in GC logs