Win a copy of The Java Performance Companion this week in the Performance forum!
  • Post Reply
  • Bookmark Topic Watch Topic
  • New Topic

Understanding the each line in GC logs

 
trupti nigam
Ranch Hand
Posts: 627
  • Mark post as helpful
  • send pies
  • Quote
  • Report post to moderator
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
Posts: 12146
30
Chrome Java Linux
  • Mark post as helpful
  • send pies
  • Quote
  • Report post to moderator
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.
 
Prabaharan Gopalan
Ranch Hand
Posts: 66
Java Linux VI Editor
  • Mark post as helpful
  • send pies
  • Quote
  • Report post to moderator
See if this is what you're looking for: http://java.sun.com/docs/hotspot/gc1.4.2/ section 2.2 Measurement
 
  • Post Reply
  • Bookmark Topic Watch Topic
  • New Topic