Logging garbage collector activity
An easy low cost method to check the activity of the garbage collector in the JVM is to tell the JVM to create an activity log. This is achieved for Sun JVMs using the non-standard command line option “-Xloggc:file_name“. This will tell the JVM to create a log file with a content similar with this:
0.806: [GC 8064K->1211K(30912K), 0.0051670 secs]
1.363: [GC 9275K->1856K(30912K), 0.0061070 secs]
1.944: [GC 9920K->2602K(30912K), 0.0115890 secs]
2.351: [GC 10666K->3289K(38976K), 0.0083440 secs]
3.159: [GC 19417K->4316K(38976K), 0.0325310 secs]
3.948: [GC 20444K->5735K(56192K), 0.0083630 secs]
35.812: [GC 37671K->7896K(56512K), 0.0152040 secs]
525.368: [GC 39832K->8066K(89600K), 0.0082710 secs]
As one can guess the log entries show the time of the garbage collection activity, the memory before and after and the duration of the garbage collection. This can prove very useful when monitoring the activity of a server application for memory leaks and for memory activity.
If the information about the garbage collection activity is only needed at the console the “-XX:+PrintGC” and “-XX:+PrintGCDetails” options can be used. The last one will produce an output with more details lke this one:
[GC [PSYoungGen: 33584K->1312K(33600K)] 36545K->6656K(55104K), 0.0141310 secs]
…
Heap
PSYoungGen total 33920K, used 8802K [0×00002aaac91c0000, 0×00002aaacd790000, 0×00002aaad39c0000)
eden space 30976K, 19% used [0×00002aaac91c0000,0×00002aaac97840a8,0×00002aaacb000000)
from space 2944K, 98% used [0×00002aaacd4b0000,0×00002aaacd784978,0×00002aaacd790000)
to space 4096K, 0% used [0×00002aaaccf90000,0×00002aaaccf90000,0×00002aaacd390000)
PSOldGen total 21504K, used 5344K [0×00002aaab41c0000, 0×00002aaab56c0000, 0×00002aaac91c0000)
object space 21504K, 24% used [0×00002aaab41c0000,0×00002aaab46f8340,0×00002aaab56c0000)
PSPermGen total 21248K, used 19211K [0×00002aaaaedc0000, 0×00002aaab0280000, 0×00002aaab41c0000)
object space 21248K, 90% used [0×00002aaaaedc0000,0×00002aaab0082d50,0×00002aaab0280000)
The behavior of the logging option seems to produce identical results as “-XX:+PrintGC” even if personally I would’ve expect more details in the log file. Maybe this will change in a future version of Java.
