File APIs for Java Developers
Manipulate DOC, XLS, PPT, PDF and many others from your application.
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
JavaRanch » Java Forums » Java » Performance
Bookmark "Understanding the each line in GC logs" Watch "Understanding the each line in GC logs" New topic

Understanding the each line in GC logs

trupti nigam
Ranch Hand

Joined: Jun 21, 2001
Posts: 614
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?


fred rosenberger
lowercase baba

Joined: Oct 02, 2003
Posts: 11955


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: section 2.2 Measurement

Googling doesn't make you a genius. But not Googling makes you dumber.
I agree. Here's the link:
subject: Understanding the each line in GC logs
It's not a secret anymore!