Garbage Collector Log File

Table of Contents

Log File from Concurrent Garbage Collection (ZST 5.21.x)
Log File from Concurrent Garbage Collection (pre ZST 5.21.0)
Log File from Stop-The-World (STW) garbage collection

Need help?

Schedule a consultation with an Azul performance expert.

The GC log files present metrics in the text format.

Log File from Concurrent Garbage Collection (ZST 5.21.x)

This log output has been generated for 5.21.0 ZST with 5.21.0 pmem.conf file

 0.092: [GCHH : Zing name : Zing 64-Bit Tiered VM mixed mode ]
0.092: [GCHH : Zing release : 1.8.0-zing_99.99.99.99.dev-b2018-product-azlinuxM-X86_64 ]
0.092: [GCHH : ZST version : zst-5.21.0.0-8 ]
0.092: [GCHH : ZST API : 0x8a ]
0.092: [GCHH : OS name : Linux ]
0.092: [GCHH : OS release : 2.6.32-358.el6.x86_64 #1 SMP Fri Feb 22 00:31:26 UTC 2013 ]
0.092: [GCHH : hardware : x86_64 ]
0.092: [GCHH : ncpus : 12 12 12 12 12 ]
0.092: [GCHH : TSC : pstate off tsc on constant_tsc on nonstop_tsc on UseRdtsc false ]
0.092: [GCHH : machine name : venison ]
0.092: [GCHH : Zing VM running in container : false ]
0.092: [GCHH : start time : Wed Sep 27 22:10:19 PDT 2017 ]
0.092: [GCHH : start time ms : 1506575419967 ]
0.092: [GCHH : process id : 18221 ]
0.092: [GCHH : sequence no. : 0 ]
0.092: [GCHH : Memory configuration and use (MB): ]
0.092: [GCHH : System RAM max : 96735 ]
0.092: [GCHH : System RAM free : 90949 ]
0.092: [GCHH : Linux Memory available : 92239 ]
0.092: [GCHH : Zing Memory configuration policy : reserve-at-launch ]
0.092: [GCHH : Zing overall upper limit : 87060 ]
0.092: [GCHH : Zing total reserved : 4496 ]
0.092: [GCHH : Zing initial reserved : 400 ]
0.092: [GCHH : Zing Reservable upper limit : 82224 ]
0.092: [GCHH : Zing Reservable reserved : 4096 ]
0.092: [GCHH : Zing Reservable initial reserved : 0 ]
0.092: [GCHH : Zing Contingency upper limit : 48366 ]
0.092: [GCHH : Zing Contingency reserved : 200 ]
0.092: [GCHH : Zing Contingency initial reserved : 200 ] pmem.conf ContingencyMinimumFreeMemory
0.092: [GCHH : Zing Pause upper limit : 48366 ]
0.092: [GCHH : Zing Pause reserved : 200 ]
0.092: [GCHH : Zing Pause initial reserved : 200 ]
0.092: [GCHH : Process Zing maximum : 15606 ]
0.092: [GCHH : Process Zing reserved (-Xmx) : 4096 ]
0.092: [GCHH : Java system max : 246 ]
0.092: [GCHH : Code cache location : Process Zing memory ]
0.092: [GCHH : Code cache max : 256 ]
0.092: [GCHH : Compiler Tier 1 : C1 ]
0.092: [GCHH : Compiler Tier 2 : Falcon ]
0.092: [GCHH : Garbage collection type : C4 ]
0.092: [GCHH : GenPauseless Phase Encoding : Sparse ]
0.092: [GCHH : jvm arguments
0.092: [GCHH : Memory configuration and use (MB): ]
0.092: [GCHH : System RAM max : 96735 ]
0.092: [GCHH : System RAM free : 90949 ]
0.092: [GCHH : Linux Memory available : 92239 ]
0.092: [GCHH : Zing Memory configuration policy : reserve-at-launch ]
0.092: [GCHH : Zing overall upper limit : 87060 ]
0.092: [GCHH : Zing total reserved : 4496 ]
0.092: [GCHH : Zing initial reserved : 400 ]
0.092: [GCHH : Zing Reservable upper limit : 82224 ]
0.092: [GCHH : Zing Reservable reserved : 4096 ]
0.092: [GCHH : Zing Reservable initial reserved : 0 ]
0.092: [GCHH : Zing Contingency upper limit : 48366 ]
0.092: [GCHH : Zing Contingency reserved : 200 ]
0.092: [GCHH : Zing Contingency initial reserved : 200 ]
0.092: [GCHH : Zing Pause upper limit : 48366 ]
0.092: [GCHH : Zing Pause reserved : 200 ]
0.092: [GCHH : Zing Pause initial reserved : 200 ]
0.092: [GCHH : Process Zing maximum : 15606 ] ** calculated
0.092: [GCHH : Process Zing reserved (-Xmx) : 4096 ]
0.092: [GCHH : Java system max : 246 ]
0.092: [GCHH : Code cache location : Process Zing memory ]
0.092: [GCHH : Code cache max : 256 ]
0.092: [GCHH : Compiler Tier 1 : C1 ]
0.092: [GCHH : Compiler Tier 2 : Falcon ]
0.092: [GCHH : Garbage collection type : C4 ]
0.092: [GCHH : jvm arguments : -Xmx16g -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=2m -Xloggc:GCLogFileRotation_%t_%p -XX:-ShowMessageBoxOnError ]
0.092: [GCHH : jvm flags : none ]
0.092: [GCHH : java command : SPECjvm2008.jar -ikv compiler.compiler ]
0.092: [GCH : heap usage MB : gens MB : heap info MB : pages : intercycle intracycle : gc : threads delay : gc pause 1 pause 2 pause 3 pause 4 : end]
0.092: [GCH type label tot_ct-cyc_ct : max peak cur ppause upause rss codec jsys : new old perm internal : live frag found cllctd lmtd : prom reloc noreloc rspike sm md lg : sec alloc-rate perm-rate sec alloc-rate perm-rate : thrds md diag : tot delayed avg max : start start dur start dur start dur start dur : end]
0.092: [SYSINFOH sysMemUsed cacheActiveFile cacheInactiveFile cacheActiveAnon cacheInactiveAnon swapCached buffers unevictable mlocked mapped : totalSysZingMemAcrossPartitions sysZingMemTot sysZingReservableUsed sysZingReservableTot sysZingContMemUsed sysZingContMemTot sysZingPPMemUsed sysZingPPMemTot : swapUsed swapMax : load1 load5 load15 : pageIn pageOut : swapPageIn swapPageOut : majorFaults cMajorFaults : processes procsRunning procsBlocked procsTotal : end(s) ]
0.092: [OBJCREATH newGen(kB) permGen(kB) oldGen(kB) : end(s)]
0.092: [GPGC-HH Model MB/sec . . : KIDRate : EstTime secs : Sizes MB . . : KIDCount : Time(secs) : Heuristic ]
0.092: [GPGC-HH NewGen OldGen PermGen Direct : KID/sec : NewGC OldGC : New Old Perm Direct : KID : Time : ReasonCode ReasonString ]
0.092: [COMPSTATSH Tier FullMethodCompiles OSRMethodCompiles MethodFailToInstall OSRFailToInstall TotalCPUTimeMS TotalWallClockTimeMS TotalWaitInQueueTimeMS : WaitTimes0ms 10ms 100ms 1000ms 10000ms 100000ms 1000000ms : CompileTimes0ms 10ms 100ms 1000ms 10000ms 100000ms 1000000ms ]
0.130: [SPSH lock suspend gclocker notify wait resuspend cleanup op_time wakeup total(ms) op_name end(s) ]
0.130: [SPS 0.000 0.000 0.002 0.001 0.000 0.000 0.001 0.009 0.003 0.014 Deoptimize 0.129941 ]
0.172: [COMPSTATS 1 100 0 0 0 0 0 1212: 43 57 0 0 0 0 0 : 96 0 0 0 0 0 0 ]
0.310: [SPS 0.000 0.000 0.001 0.001 0.000 0.000 0.001 0.111 0.006 0.120 NewGC_pause1 0.310534 ]
0.320: [SPS 0.000 0.000 0.000 0.001 0.000 0.000 0.001 0.218 0.003 0.223 NewGC_pause2 0.320863 ]
0.331: [SPS 0.000 0.000 0.000 0.001 0.000 0.000 0.001 0.011 0.002 0.015 NewGC_pause3 0.331900 ]
0.341: [SPS 0.000 0.000 0.000 0.001 0.000 0.000 0.001 0.143 0.002 0.146 OldGC_pause2 0.342170 ]
0.352: [SPS 0.000 0.000 0.000 0.001 0.000 0.000 0.001 0.007 0.001 0.010 OldGC_pause3 0.352657 ]
0.363: [SPS 0.000 0.003 0.000 0.001 0.000 0.000 0.001 0.039 0.002 0.042 NewGC_pause4 0.363751 ]
0.365: [GC NTO Sys 1-1 : 16384 1182 1178 0 0 59 0 2 : 19 0 11 1152 : 7 15 6 5 0 : 0 8 3 2 10 0 0 : 0.238 67.3 42.1 0.056 70.9 35.5 : 6 -pc 000 : 26 0 0.000 0.000 : 0.309361 0.310414 0.000111 0.320640 0.000218 0.331885 0.000011 0.363710 0.000038 : 0.365770 ]
0.365: [SYSINFO 92696 10312 8443 73 69 2 295 0 0 27 : - 72550 16384 65298 0 3626 0 3626 : 14 4095 : 0.00 0.95 2.54 : 827392 98723748 : 3521 6816 : 15 0 : 4064482 3 0 410 : 0.366038 ]
0.365: [OBJCREAT 8291 7397 - : 0.366072 ]

Log File from Concurrent Garbage Collection (pre ZST 5.21.0)

This log output has been generated for pre 5.21.0 ZST with pre 5.21.0 pmem.conf file

 0.092: [GCHH : Zing name : Zing 64-Bit Tiered VM mixed mode ]
0.092: [GCHH : Zing release : 1.7.0-zing_99.99.99.99.dev-b1104-product-azlinuxM-X86_64-jcoha ]
0.092: [GCHH : ZST version : zst-dev-1162 ]
0.092: [GCHH : ZST internal : 0x7c ]
0.092: [GCHH : OS name : Linux ]
0.092: [GCHH : OS release : 2.6.32-504.el6.x86_64 #1 SMP Wed Oct 15 04:27:16 UTC 2014 ]
0.092: [GCHH : hardware : x86_64 ]
0.092: [GCHH : ncpus : 12 12 12 12 12 ]
0.092: [GCHH : machine name : perfs ]
0.092: [GCHH : Zing VM running in container : false ] Is the ZVM running in a container?
0.092: [GCHH : start time : Sat Sep 05 10:12:20 PDT 2015 ]
0.092: [GCHH : start time ms : 1441473140016 ]
0.092: [GCHH : process id : 6837
0.092: [GCHH : sequence no. : 0 ] Used for GC log file rotation
0.092: [GCHH : Memory configuration and use (MB): ]
0.092: [GCHH : System RAM max : 48258 ]
0.092: [GCHH : System RAM free : 10337 ]
0.092: [GCHH : Linux Memory max : 12066 ]
0.092: [GCHH : Zing Memory configuration policy : reserve-at-config ]
0.092: [GCHH : Zing Reservable max : 32576 ]
0.092: [GCHH : Zing Contingency max : 1808 ]
0.092: [GCHH : Zing Pause max : 1808 ]
0.092: [GCHH : Process Zing reserved (-Xmx) : 2048 ]
0.092: [GCHH : Java system max : 124 ]
0.092: [GCHH : Code cache max : 256 ]
0.092: [GCHH : Compiler Tier 1 : C1 ]
0.092: [GCHH : Compiler Tier 2 : Falcon ]
0.092: [GCHH : Garbage collection type : C4 ]
0.092: [GCHH : jvm arguments : -Xmx16g -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=2m -Xloggc:GCLogFileRotation_%t_%p -XX:-ShowMessageBoxOnError ]
0.092: [GCHH : jvm flags : none ]
0.092: [GCHH : java command : SPECjvm2008.jar -ikv compiler.compiler ]
0.092: [GCH : heap usage MB : gens MB : heap info MB : pages : intercycle intracycle : gc : threads delay : gc pause 1 pause 2 pause 3 pause 4 : end]
0.092: [GCH type label tot_ct-cyc_ct : max peak cur ppause upause rss codec jsys : new old perm internal : live frag found cllctd lmtd : prom reloc noreloc rspike sm md lg : sec alloc-rate perm-rate sec alloc-rate perm-rate : thrds md diag : tot delayed avg max : start start dur start dur start dur start dur : end]
0.092: [SYSINFOH sysMemUsed cacheActiveFile cacheInactiveFile cacheActiveAnon cacheInactiveAnon swapCached buffers unevictable mlocked mapped : totalSysZingMemAcrossPartitions sysZingMemTot sysZingReservableUsed sysZingReservableTot sysZingContMemUsed sysZingContMemTot sysZingPPMemUsed sysZingPPMemTot : swapUsed swapMax : load1 load5 load15 : pageIn pageOut : swapPageIn swapPageOut : majorFaults cMajorFaults : processes procsRunning procsBlocked procsTotal : end(s) ]
0.092: [OBJCREATH newGen(kB) permGen(kB) oldGen(kB) : end(s)]
0.092: [GPGC-HH Model MB/sec . . : KIDRate : EstTime secs : Sizes MB . . : KIDCount : Time(secs) : Heuristic ]
0.092: [GPGC-HH NewGen OldGen PermGen Direct : KID/sec : NewGC OldGC : New Old Perm Direct : KID : Time : ReasonCode ReasonString ]
0.092: [COMPSTATSH Tier FullMethodCompiles OSRMethodCompiles MethodFailToInstall OSRFailToInstall TotalCPUTimeMS TotalWallClockTimeMS TotalWaitInQueueTimeMS : WaitTimes0ms 10ms 100ms 1000ms 10000ms 100000ms 1000000ms : CompileTimes0ms 10ms 100ms 1000ms 10000ms 100000ms 1000000ms ]
0.130: [SPSH lock suspend gclocker notify wait resuspend cleanup op_time wakeup total(ms) op_name end(s) ]
0.130: [SPS 0.000 0.000 0.002 0.001 0.000 0.000 0.001 0.009 0.003 0.014 Deoptimize 0.129941 ]
0.172: [COMPSTATS 1 100 0 0 0 0 0 1212: 43 57 0 0 0 0 0 : 96 0 0 0 0 0 0 ]
0.310: [SPS 0.000 0.000 0.001 0.001 0.000 0.000 0.001 0.111 0.006 0.120 NewGC_pause1 0.310534 ]
0.320: [SPS 0.000 0.000 0.000 0.001 0.000 0.000 0.001 0.218 0.003 0.223 NewGC_pause2 0.320863 ]
0.331: [SPS 0.000 0.000 0.000 0.001 0.000 0.000 0.001 0.011 0.002 0.015 NewGC_pause3 0.331900 ]
0.341: [SPS 0.000 0.000 0.000 0.001 0.000 0.000 0.001 0.143 0.002 0.146 OldGC_pause2 0.342170 ]
0.352: [SPS 0.000 0.000 0.000 0.001 0.000 0.000 0.001 0.007 0.001 0.010 OldGC_pause3 0.352657 ]
0.363: [SPS 0.000 0.003 0.000 0.001 0.000 0.000 0.001 0.039 0.002 0.042 NewGC_pause4 0.363751 ]
0.365: [GC NTO Sys 1-1 : 16384 1182 1178 0 0 59 0 2 : 19 0 11 1152 : 7 15 6 5 0 : 0 8 3 2 10 0 0 : 0.238 67.3 42.1 0.056 70.9 35.5 : 6 -pc 000 : 26 0 0.000 0.000 : 0.309361 0.310414 0.000111 0.320640 0.000218 0.331885 0.000011 0.363710 0.000038 : 0.365770 ]
0.365: [SYSINFO 92696 10312 8443 73 69 2 295 0 0 27 : - 72550 16384 65298 0 3626 0 3626 : 14 4095 : 0.00 0.95 2.54 : 827392 98723748 : 3521 6816 : 15 0 : 4064482 3 0 410 : 0.366038 ]
0.365: [OBJCREAT 8291 7397 - : 0.366072 ]

Log File from Stop-The-World (STW) garbage collection

The STW garbage collector mode can be enabled by using the -XX:+UseSTW command-line option. In this mode the set of the metrics collected in the log file might be different.

 0.091: [GCHH : Zing name : Zing 64-Bit Tiered VM mixed mode ]
0.091: [GCHH : Zing release : 1.7.0-zing_17.06.0.0-b5-product-azlinuxM-X86_64 ]
0.091: [GCHH : ZST version : zst-dev-1705 ]
0.091: [GCHH : ZST API : 0x7e ]
0.091: [GCHH : OS name : Linux ]
0.091: [GCHH : OS release : 2.6.32-358.el6.x86_64 #1 SMP Fri Feb 22 00:31:26 UTC 2013 ]
0.091: [GCHH : hardware : x86_64 ]
0.091: [GCHH : ncpus : 12 12 12 12 12 ]
0.091: [GCHH : TSC : pstate off tsc on constant_tsc on nonstop_tsc on UseRdtsc false ]
0.091: [GCHH : machine name : development1 ]
0.091: [GCHH : Zing VM running in container : false ]
0.091: [GCHH : start time : Mon Jun 12 20:24:18 PDT 2017 ]
0.091: [GCHH : start time ms : 1497324258281 ]
0.091: [GCHH : process id : 29231 ]
0.091: [GCHH : sequence no. : 0 ]
0.091: [GCHH : Memory configuration and use (MB): ]
0.091: [GCHH : System RAM max : 96735 ]
0.091: [GCHH : System RAM free : 3958 ]
0.091: [GCHH : Linux Memory max : 24185 ]
0.091: [GCHH : Zing Memory configuration policy : reserve-at-config ]
0.091: [GCHH : Zing Memory partition size : 72550 ]
0.091: [GCHH : Zing Reservable max : 65298 ]
0.091: [GCHH : Zing Contingency max : 3626 ]
0.091: [GCHH : Zing Pause max : 3626 ]
0.091: [GCHH : Process Zing reserved (-Xmx) : 16384 ]
0.091: [GCHH : Java system max : 380 ]
0.091: [GCHH : Code cache location : Process Zing memory ]
0.091: [GCHH : Code cache max : 256 ]
0.091: [GCHH : Compiler Tier 1 : C1 ]
0.091: [GCHH : Compiler Tier 2 : Falcon ]
0.091: [GCHH : Garbage collection type : STW ]
0.091: [GCHH : jvm arguments : -Xmx16g -XX:+UseSTW -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=2m -Xloggc:GCLogFileRotation_%t_%p -XX:-ShowMessageBoxOnError ]
0.091: [GCHH : jvm flags : none ]
0.091: [GCHH : java command : SPECjvm2008.jar -ikv compiler.compiler ]
0.091: [GCH : heap usage MB : gens MB : heap info MB : pages : intercycle intracycle : gc : threads delay : gc pause 1 pause 2 pause 3 pause 4 : end]
0.091: [GCH type label tot_ct-cyc_ct : max peak cur ppause upause rss codec jsys : new old perm internal : live frag found cllctd lmtd : prom reloc noreloc rspike sm md lg : sec alloc-rate perm-rate sec alloc-rate perm-rate : thrds md diag : tot delayed avg max : start start dur start dur start dur start dur : end]
0.091: [SYSINFOH sysMemUsed cacheActiveFile cacheInactiveFile cacheActiveAnon cacheInactiveAnon swapCached buffers unevictable mlocked mapped : totalSysZingMemAcrossPartitions sysZingMemTot sysZingReservableUsed sysZingReservableTot sysZingContMemUsed sysZingContMemTot sysZingPPMemUsed sysZingPPMemTot : swapUsed swapMax : load1 load5 load15 : pageIn pageOut : swapPageIn swapPageOut : majorFaults cMajorFaults : processes procsRunning procsBlocked procsTotal : end(s) ]
0.091: [OBJCREATH newGen(kB) permGen(kB) oldGen(kB) : end(s)]
0.091: [GPGC-HH Model MB/sec . . : KIDRate : EstTime secs : Sizes MB . . : KIDCount : Time(secs) : Heuristic ]
0.091: [GPGC-HH NewGen OldGen PermGen Direct : KID/sec : NewGC OldGC : New Old Perm Direct : KID : Time : ReasonCode ReasonString ]
0.091: [COMPSTATSH Tier FullMethodCompiles OSRMethodCompiles MethodFailToInstall OSRFailToInstall TotalCPUTimeMS TotalWallClockTimeMS TotalWaitInQueueTimeMS : WaitTimes0ms 10ms 100ms 1000ms 10000ms 100000ms 1000000ms : CompileTimes0ms 10ms 100ms 1000ms 10000ms 100000ms 1000000ms ]
0.130: [SPSH lock suspend gclocker notify wait resuspend cleanup op_time wakeup total(ms) op_name end(s) ]
0.130: [SPS 0.000 0.000 0.002 0.001 0.000 0.000 0.001 0.009 0.003 0.014 Deoptimize 0.129890 ]
0.172: [COMPSTATS 1 100 0 0 0 0 0 1212: 43 57 0 0 0 0 0 : 96 0 0 0 0 0 0 ]
0.458: [SPS 0.000 0.000 0.001 0.001 0.000 0.000 0.002 146.245 0.004 146.253 FullGC_STW_pause 0.459151 ]
0.459: [GC NTO Sys 1-1 : 16384 1210 1208 0 0 64 0 2 : 15 0 11 1183 : 3 11 6 5 0 : 0 8 0 0 8 0 0 : 0.240 66.6 41.6 0.150 0.0 13.4 : 12 -pc 000 : 24 0 0.000 0.000 : 0.309633 0.312897 0.146246 0.000000 0.000000 0.000000 0.000000 0.000000 0.000000 : 0.459366 ]
0.459: [SYSINFO 92797 10346 8498 76 71 2 295 0 0 27 : - 72550 16384 65298 0 3626 0 3626 : 14 4095 : 3.75 0.90 1.25 : 827392 98801116 : 3521 6816 : 0 0 : 4065048 4 0 423 : 0.459810 ]
0.459: [OBJCREAT 8288 7402 - : 0.459895 ]
0.459: [GC Old Sys 2-1 : 16384 1210 1208 0 0 64 0 2 : 17 0 11 1183 : 7 2 1 0 0 : 0 2 0 0 6 0 0 : 0.242 0.0 41.3 0.148 0.0 13.5 : 12 -pc 000 : 24 - - - : 0.311524 0.312897 0.146246 0.000000 0.000000 0.000000 0.000000 0.000000 0.000000 : 0.459501 ]
0.459: [SYSINFO 92797 10346 8498 76 71 2 295 0 0 27 : - 72550 16384 65298 0 3626 0 3626 : 14 4095 : 3.75 0.90 1.25 : 827392 98801116 : 3521 6816 : 0 0 : 4065048 4 0 423 : 0.459913 ]
0.459: [OBJCREAT 8288 7402 - : 0.459957 ]

Note

In STW mode, there is only one pause for each type of garbage collection (NewGC_STW and FullGC_STW_pause_pause) unlike in concurrent mode, where each GC type has four pauses (NewGC_pause1, NewGC_pause2, NewGC_pause3, and NewGC_pause4). In STW mode in the line printed for each garbage collection, the single the pause at each collection corresponds to pause 1, and the pause 2, pause 3, and pause 4 times and duration are all zero.