Java GC Tutorials - Herong's Tutorial Examples

∟JVM Garbage Collection Logging

∟"-Xlog:gc*=trace" - Maximum GC Logging

This section describes the garbage collection logging option '-Xlog:gc*=trace' (the maximum GC logging option), which prints log messages from all GC sources with the lowest log level of TRACE.

In this tutorial, let's try the maximum logging option "-Xlog:gc*=trace", prints out log messages in all GC sources at the lowest level: 

herong> java -Xms2m -Xmx64m -Xlog:gc*=trace:gc.log GarbageCollection

Step/TotalMemory/FreeMemory/UsedMemory:
1   2031616   698408   1333208
2   3874816   1472824   2401992
3   3874816   424944   3449872
4   8970240   4441352   4528888
...
(Ctrl-C)

herong> more gc.log
[0.006s][trace][gc] MarkStackSize: 4096k  MarkStackSizeMax: 16384k ...
[0.012s][info ][gc,heap] Heap region size: 1M                      ...
[0.012s][debug][gc,heap] Minimum heap 2097152  Initial heap 2097152...
[0.012s][trace][gc,heap,coops] Trying to allocate at address 0x0000...
[0.012s][trace][gc,barrier   ] G1CardTable::G1CardTable:           ...
[0.012s][trace][gc,barrier   ]     &_byte_map[0]: 0x000001fe0048000...
[0.012s][trace][gc,barrier   ]     _byte_map_base: 0x000001fdffca00...
[0.012s][trace][gc,bot       ] G1BlockOffsetTable::G1BlockOffsetTab...
[0.012s][trace][gc,bot       ]     rs.base(): 0x000001fe00460000  r...
[0.013s][trace][gc,task      ] WorkerManager::add_workers() : creat...
[0.013s][trace][gc,task      ] Adding initial GC Thread(s) previous...
[0.013s][debug][gc           ] ConcGCThreads: 2 offset 16          ...
[0.013s][debug][gc           ] ParallelGCThreads: 8                ...
                                   ...
[0.014s][debug][gc           ] Initialize mark stack with 4096 chun...
[0.014s][debug][gc,ergo,heap ] Expand the heap. requested expansion...
[0.014s][trace][gc,region    ] G1HR COMMIT(FREE) [...
[0.014s][trace][gc,region    ] G1HR COMMIT(FREE) [...
[0.014s][debug][gc,ihop      ] Target occupancy update: old: 0B, ne...
[0.014s][debug][gc,ergo,refine] Initial Refinement Zones: green: 8,...
                                   ...
[0.015s][info ][gc            ] Using G1                           ...
[0.015s][info ][gc,heap,coops ] Heap address: 0x00000000fc000000, s...
[0.016s][trace][gc,metaspace  ] node @0x000001fe024c4cc0: reserved=...
[0.016s][trace][gc,metaspace  ]    [...
[0.016s][trace][gc,metaspace  ] Narrow klass base: 0x00000008000000...
[0.016s][trace][gc,metaspace  ] Compressed class space size: 107374...
[0.016s][trace][gc,metaspace  ] node @0x000001fe024c97d0: reserved=...
[0.016s][trace][gc,metaspace  ]    [0x000001fe1c680000, 0x000001fe1...
                                   ...
[0.017s][trace][gc,tlab       ] ThreadLocalAllocBuffer::compute_siz...
[0.017s][trace][gc,region     ] G1HR ALLOC(EDEN) [...
[0.017s][trace][gc,tlab       ] TLAB: fill thread: 0x000001fe024c80...
[0.019s][trace][gc,tlab       ] ThreadLocalAllocBuffer::compute_siz...
[0.019s][trace][gc,tlab       ] TLAB: fill thread: 0x000001fe024c80...
[0.020s][trace][gc,metaspace,freelist] SpaceManager(): 0x000001fe02...
[0.020s][trace][gc,metaspace,freelist] SpaceManager(): 0x000001fe02...
[0.020s][trace][gc,metaspace,freelist] allowed expansion words: 230...
[0.020s][trace][gc,metaspace,freelist] Expanded non-class virtual s...
[0.020s][trace][gc,metaspace,freelist] Expanded non-class virtual s...
[0.020s][trace][gc,metaspace,freelist] SpaceManager::added chunk:  ...
[0.020s][trace][gc,metaspace,freelist] Metachunk: bottom 0x000001fe...
[0.020s][trace][gc,metaspace,freelist] Free chunk total 0  count 0 ...
[0.020s][trace][gc,metaspace,freelist] allowed expansion words: 230...
[0.020s][trace][gc,metaspace,freelist] Expanded class virtual space...
[0.020s][trace][gc,metaspace,freelist] Expanded class virtual space...
[0.020s][trace][gc,metaspace,freelist] SpaceManager::added chunk:  ...
[0.020s][trace][gc,metaspace,freelist] Metachunk: bottom 0x00000008...
[0.020s][trace][gc,metaspace,freelist] Free chunk total 0  count 0 ...
[0.022s][trace][gc,tlab] ThreadLocalAllocBuffer::compute_size(13) r...
[0.022s][trace][gc,tlab] TLAB: fill thread: 0x000001fe024c8000 [id:...
                                   ...
[0.033s][info ][gc     ] Periodic GC disabled                      ...
...                                                                ...

[0.063s][trace][gc,task       ] WorkerManager::add_workers() : crea...
[0.063s][trace][gc,task       ] GC Thread: using 1 out of 8 workers...
[0.063s][trace][gc,task       ] WorkerManager::add_workers() : crea...
[0.063s][trace][gc,task       ] GC Thread: using 1 out of 8 workers...
[0.063s][trace][gc,nmethod    ] oops_do_marking_epilogue           ...
                                   ...
[0.063s][debug][gc,heap       ] GC(0) Heap before GC invocations=0 ...
[0.063s][debug][gc,heap       ] GC(0)   region size 1024K, 1 young ...
[0.063s][debug][gc,heap       ] GC(0)  Metaspace       used 329K, c...
[0.063s][debug][gc,heap       ] GC(0)   class space    used 30K, ca...
[0.063s][trace][gc,heap,region] GC(0) Heap Regions: E=young(eden), ...
[0.063s][trace][gc,heap,region] GC(0) |   0|0x00000000fc000000, 0x0...
[0.063s][trace][gc,heap,region] GC(0) |   1|0x00000000fc100000, 0x0...
[0.063s][info ][gc,start      ] GC(0) Pause Young (Normal) (G1 Evac...
[0.063s][trace][gc,task       ] GC(0) WorkerPolicy::calc_default_ac...
[0.064s][trace][gc,task       ] GC(0) WorkerManager::add_workers() ...
[0.064s][trace][gc,task       ] GC(0) Creating additional GC Thread...
[0.064s][trace][gc,task       ] GC(0) GC Thread: using 2 out of 8 w...
[0.064s][info ][gc,task       ] GC(0) Using 2 workers of 8 for evac...
[0.064s][trace][gc,tlab       ] GC(0) TLAB: gc thread: 0x000001fe02...
[0.064s][trace][gc,tlab       ] GC(0) TLAB: gc thread: 0x000001fe02...
...                                                                ...
[0.064s][debug][gc,alloc,region] GC(0) Mutator Allocation stats, re...
[0.064s][debug][gc,age         ] GC(0) Desired survivor size 524288...
[0.064s][trace][gc,ergo,cset   ] GC(0) Start choosing CSet. pending...
[0.064s][trace][gc,ergo,cset   ] GC(0) Add young regions to CSet. e...
[0.064s][debug][gc,ergo,cset   ] GC(0) Finish choosing CSet regions...
[0.064s][trace][gc,region      ] GC(0) G1HR CSET(EDEN) [...
[0.064s][trace][gc,nmethod     ] GC(0) oops_do_marking_prologue    ...
[0.064s][debug][gc,task,stats  ] GC(0) GC Termination Stats        ...
[0.064s][debug][gc,task,stats  ] GC(0)      elapsed  --strong roots...
[0.064s][debug][gc,task,stats  ] GC(0) thr     ms        ms      % ...
[0.064s][debug][gc,task,stats  ] GC(0) --- --------- --------- ----...
[0.064s][trace][gc,task        ] GC(0) WorkerManager::add_workers()...
[0.064s][trace][gc,task        ] GC(0) GC Thread: using 2 out of 8 ...
[0.064s][trace][gc,region      ] GC(0) G1HR ALLOC(SURV) [...
[0.064s][trace][gc,nmethod     ] GC(0)  116       3       java.util...
...                                                                ...
[0.065s][debug][gc,task,stats  ] GC(0)   1      0.95      0.94  99....
[0.065s][debug][gc,task,stats  ] GC(0)   0      1.00      0.79  79....
[0.065s][trace][gc,task        ] GC(0) WorkerManager::add_workers()...
[0.065s][trace][gc,task        ] GC(0) GC Thread: using 2 out of 8 ...
[0.065s][trace][gc,nmethod     ] GC(0)   54       3       java.lang...
...                                                                ...
[0.065s][trace][gc,nmethod     ] GC(0)  116       3       java.util...
[0.065s][trace][gc,nmethod     ] GC(0) oops_do_marking_epilogue    ...
[0.065s][debug][gc,ergo        ] GC(0) Running G1 Clear Card Table ...
[0.065s][trace][gc,task        ] GC(0) WorkerManager::add_workers()...
[0.065s][trace][gc,task        ] GC(0) GC Thread: using 1 out of 8 ...
[0.066s][trace][gc,task        ] GC(0) WorkerManager::add_workers()...
[0.066s][trace][gc,task        ] GC(0) GC Thread: using 2 out of 8 ...
[0.066s][debug][gc,ref         ] GC(0) Skipped phase1 of Reference ...
[0.066s][trace][gc,ref         ] GC(0) Phase2 Soft before0 0 0 0 0 ...
[0.066s][trace][gc,ref         ] GC(0) Phase2 Weak before0 81 0 0 0...
[0.066s][trace][gc,ref         ] GC(0) Phase2 Final before0 0 0 0 0...
[0.066s][trace][gc,ref         ] GC(0) Phase2 Final after0 0 0 0 0 ...
[0.066s][debug][gc,ref         ] GC(0) Skipped phase3 of Reference ...
[0.066s][trace][gc,ref         ] GC(0) Phase4 Phantom before0 14 0 ...
...

Wow! I am very impressed on how much information we can get with the maximum GC logging option "-Xlog:gc*=trace".

But getting so much information could make it difficult for us understand. So may we should raise the log level to DEBUG with "-Xlog:gc*=debug".

Table of Contents

 About This Book

 Heap Memory Area and Size Control

►JVM Garbage Collection Logging

 Garbage Collection Demo Program

 Garbage Collection Logging Options

 "-Xlog:gc" - Default GC Logging Level: INFO

 "-Xlog:gc=trace" - Lowest GC Logging Level: TRACE

 "-Xlog:gc+heap=trace" - GC+HEAP Log Messages

►"-Xlog:gc*=trace" - Maximum GC Logging

 "-XX:+PrintFlagsFinal" - Print JVM Options

 Introduction of Garbage Collectors

 Serial Collector - "+XX:+UseSerialGC"

 Parallel Collector - "+XX:+UseParallelGC"

 Concurrent Mark-Sweep (CMS) Collector - "+XX:+UseConcMarkSweepGC"

 Garbage First (G1) Collector - "+XX:+UseG1GC"

 The Z Garbage Collector (ZGC) - "+XX:+UseZGC"

 Object References and Garbage Collection

 Garbage Collection Performance Test Program

 Performance Tests on Serial Collector

 Performance Tests on Parallel collector

 Performance Tests on Concurrent collector

 Performance Tests on G1 collector

 Garbage Collection Performance Test Summary

 References

 Full Version in PDF/EPUB