4.8 verbosegc

使用-verbosegc参数，可以查看垃圾收集的一些信息

4.8.1 System.gc()的verbosegc输出

<GC(3): GC cycle started Tue Mar 19 08:24:34 2002

<GC(3): freed 58808 bytes, 27% free (1163016/4192768), in 14 ms>

<GC(3): mark: 13 ms, sweep: 1 ms, compact: 0 ms>

<GC(3): refs: soft 0 (age >= 32), weak 0, final 0, phantom 0>

图表 13 System.gc的verbosegc输出

图表13是System.gc()的verbosegc输出示例。开始的GC(3)表示这是第3次进行垃圾收集，第1行显示垃圾收集开始的时间，第2行表示释放了58808字节的空间，最终堆有27%的空闲空间，耗时14ms，圆括弧中为空闲的字节数以及堆的总大小。第3行是标识、清理以及压缩阶段分别的耗时。在本例中，由于未发生压缩动作，所以压缩阶段的耗时为0ms。最后一行表示本次垃圾收集找到的被引用对象数量，在本例中，未找到引用对象。

4.8.2 分配失败的verbosegc输出

<AF[5]: Allocation Failure. need 32 bytes, 286 ms since last AF>

<AF[5]: managing allocation failure, action=1 (0/6172496) (247968/248496)>

<GC(6): GC cycle started Tue Mar 19 08:24:46 2002

<GC(6): freed 1770544 bytes, 31% free (2018512/6420992), in 25 ms>

<GC(6): mark: 23 ms, sweep: 2 ms, compact: 0 ms>

<GC(6): refs: soft 1 (age >= 4), weak 0, final 0, phantom 0>

<AF[5]: completed in 26 ms>

图表 14 分配失败的verbosegc输出

图表14是分配失败（AF）导致的垃圾收集的verbosegc输出。分配失败并不是说在代码中发生了错误，只是在无法获取足够的空闲空间时的一个触发事件。其中包含了和System.gc()相同的几行输出。AF[5]表示是第5次分配失败触发的垃圾收集。第1行表示发生分配失败时实际需要的空间，以及距离上一次分配失败发生的时间间隔。第2行表示针对分配失败，垃圾收集器采取的动作，以及堆中空闲空间和荒地的大小。可能的分配失败对应动作为：

· 0 - 垃圾收集器试图从固化空闲链表中进行分配，但是失败了

· 1 - 垃圾收集器避免使用荒地，为了避免压缩动作，荒地留作大对象分配使用

· 2 - 垃圾收集器试图在荒地之外进行分配，但是失败了

· 3 - 垃圾收集器尝试扩展堆

· 4 - 垃圾收集器准备清理SoftReference。仅会在进行了完全的扩展之后，堆空闲还低于12%的情况下发生

· 5 - 仅在resettable 虚拟机发生。表示垃圾收集器试图从临时堆申请空间

· 6 - 不是一个动作，只是表示堆内空闲空间太少了

最后一行表示分配失败的耗时，包括停止以及重新启动应用线程的时间在内。

4.8.3 堆扩展的verbosegc输出

<AF[11]: Allocation Failure. need 24 bytes, 182 ms since last AF>

<AF[11]: managing allocation failure, action=1 (0/6382368) (10296/38624)>

<GC(12): GC cycle started Tue Mar 19 08:24:49 2002

<GC(12): freed 1877560 bytes, 29% free (1887856/6420992), in 21 ms>

<GC(12): mark: 19 ms, sweep: 2 ms, compact: 0 ms>

<GC(12): refs: soft 0 (age >= 32), weak 0, final 0, phantom 0>

<AF[11]: managing allocation failure, action=3 (1887856/6420992)>

<GC(12): need to expand mark bits for 7600640-byte heap>

<GC(12): expanded mark bits by 16384 to 118784 bytes>

<GC(12): need to expand alloc bits for 7600640-byte heap>

<GC(12): expanded alloc bits by 16384 to 118784 bytes>

<GC(12): expanded heap by 1179648 to 7600640 bytes, 40% free>

<AF[11]: completed in 31 ms>

图表 15 堆扩展的verbosegc输出

图表15是包含分配失败以及堆扩展在内的verbosegc输出示例。包含了标识集合、分配集合以及堆分别扩展的大小，还有堆的空闲率。在本例中，堆扩展了1179648字节，空闲率是40%。

4.8.4 堆收缩的verbosegc输出

<AF[9]: Allocation Failure. need 32 bytes, 92 ms since last AF>

<AF[9]: managing allocation failure, action=1 (0/22100560) (1163184/1163184)>

<GC(9): may need to shrink mark bits for 22149632-byte heap>

<GC(9): shrank mark bits to 348160>

<GC(9): may need to shrink alloc bits for 22149632-byte heap>

<GC(9): shrank alloc bits to 348160>

<GC(9): shrank heap by 1114112 to 22149632 bytes, 79% free>

<GC(9): GC cycle started Tue Mar 19 11:08:18 2002

<GC(9): freed 17460600 bytes, 79% free (17509672/22149632), in 7 ms>

<GC(9): mark: 4 ms, sweep: 3 ms, compact: 0 ms>

<GC(9): refs: soft 0 (age >= 6), weak 0, final 0, phantom 0>

<AF[9]: completed in 8 ms>

图表 16 堆收缩的verbosegc输出

图表16是堆收缩的verbosegc输出，和堆扩展的输出非常类似。包含了标识集合、分配集合以及堆分别收缩的大小，还有堆的空闲率。在本例中，堆收缩了1114112字节，空闲率为79%。堆扩展和堆收缩的verbosegc输出的不同在于堆扩展是在所有的线程恢复运行之后进行，而堆收缩是在所有的线程恢复运行之前进行的。

4.8.5 压缩动作的verbosegc输出

<AF[2]: Allocation Failure. need 88 bytes, 5248 ms since last AF>

<AF[2]: managing allocation failure, action=1 (0/4032592) (160176/160176)>

<GC(2): GC cycle started Tue Mar 19 11:32:28 2002

<GC(2): freed 1165360 bytes, 31% free (1325536/4192768), in 63 ms>

<GC(2): mark: 13 ms, sweep: 1 ms, compact: 49 ms>

<GC(2): refs: soft 0 (age >= 32), weak 0, final 3, phantom 0>

<GC(2): moved 32752 objects, 2511088 bytes, reason=2, used 8 more bytes>

<AF[2]: completed in 64 ms>

图表 17压缩动作的verbosegc输出

图表17是压缩动作的verbosegc输出，和普通的分配失败输出的主要不同是包含了移动的对象的数量，移动的字节的数量，引发压缩的原因以及额外使用了多少字节。对于已经产生哈希值的对象，垃圾收集器移动他的时候需要额外的空间，因为重新生成哈希值可能会导致对象的大小增加。如果是增量压缩，“reason”字段就是“IC reason”。可能的原因如下：

· 1 - 标识和清理之后，尚未获得满足分配需求的空间

· 2 - 堆内产生碎片，需要进行压缩

· 3 - 空闲空间小于-Xminf的一半，空闲空间加上“暗物质”的大小小于-Xminf

· 4 - System.gc()

· 5 - 空闲空间低于5%

· 6 - 空闲空间低于128KB

· 7 - 设置了-Xcompactgc参数

· 8 - 临时堆的空闲空间低于5%

· 11 - 堆收缩之前的压缩动作

· 12 - 过多的暗物质导致增量压缩

· 13 - 设置了-Xpartialcompactgc参数

· 14 - 由于荒地的扩展导致增量压缩发生

· 15 - 由于荒地空间不足导致增量压缩发生

4.8.6 并发标识开始的verbosegc输出

<CONCURRENT GC Free= 379544 Expected free space= 378884 Kickoff=379406>

< Initial Trace rate is 8.01>

图表 18 并发标识开始的verbosegc输出

图表18中的verbosegc输出显示了并发标识的开始。第1行表示堆空闲字节数，以及在本次锁堆分配之后，会有多少的可用空间。Kickoff表示并发标识开始的级别。在本例中，期望的堆大小是378884字节，小于Kickoff的值379406字节。第2行表示初始的追踪率。在本例中是8.01，其含义是在本次锁堆分配中，每分配1个字节，垃圾收集器需要追踪8.01字节的活动对象。

4.8.7 System.gc()并发标识的verbosegc输出

<GC(23): Bytes Traced =0 (Foreground: 0+ Background: 0) State = 3 >

<GC(23): GC cycle started Fri Oct 11 08:45:34 2002

<GC(23): freed 12847376 bytes, 94% free (127145208/134216192), in 975 ms>

<GC(23): mark: 408 ms, sweep: 70 ms, compact: 497 ms>

<GC(23): refs: soft 0 (age >= 32), weak 0, final 0, phantom 0>

<GC(23): moved 95811 objects, 6316896 bytes, reason=4>

图表 19 System.gc()的并发标识verbosegc输出

图表19为System.gc()的并发标识verbosegc输出。第1行含有一个数字表示的状态。可能的值为：

· HALTED (0)

· EXHAUSTED (1)

· EXHAUSTED_BK_HELPER (2)

· ABORTED (3)

在本例中，State为3，说明并发标识未完成初始化阶段的工作，所以被终止。还有在并发标识阶段已经追踪的字节数，前台和后台分别计数。

4.8.8 分配失败的并发标识verbosegc输出

<AF[7]: Allocation Failure. need 528 bytes, 493 ms since last AF or CON>

<AF[7]: managing allocation failure, action=1 (0/3983128) (209640/209640)>

<GC(8): Bytes Traced =670940 (Foreground: 73725+ Background: 597215) State = 0

<GC(8): GC cycle started Tue Oct 08 13:43:14 2002

<GC(8): freed 2926496 bytes, 74% free (3136136/4192768), in 8 ms>

<GC(8): mark: 7 ms, sweep: 1 ms, compact: 0 ms>

<GC(8): refs: soft 0 (age >= 32), weak 0, final 0, phantom 0>

<AF[7]: completed in 10 ms>

图表 20 分配失败的并发标识verbosegc输出

图表20是分配失败触发的带有并发标识的垃圾收集的verbosegc输出。

Traced值表示应用线程追踪的字节数和后台线程追踪的字节数的总和，括弧中是应用线程和后台线程分别追踪的字节数。State为0，表示并发标识的状态为HALTED。

4.8.9 带有:Xgccon参数的分配失败的并发标识verbosegc输出

<AF[19]: Allocation Failure. need 65552 bytes, 106 ms since last AF or CON>

<AF[19]: managing allocation failure, action=1 (83624/16684008) (878104/878104)>

<GC(20): Bytes Traced =1882061 (Foreground: 1292013+ Background: 590048) State = 0 >

<GC(20): Card Cleaning Done. Cleaned:27 (0 skipped). Estimation 593 (Factor 0.017)>

<GC(20): GC cycle started Fri Oct 11 10:23:49 2002

<GC(20): freed 8465280 bytes, 53% free (9427008/17562112), in 9 ms>

<GC(20): mark: 7 ms, sweep: 2 ms, compact: 0 ms>

<GC(20): In mark: Final dirty Cards scan: 41 cards

<GC(20): refs: soft 0 (age >= 6), weak 0, final 0, phantom 0>

图表 21带有:Xgccon参数的分配失败的并发标识verbosegc输出

图表12是带有:Xgccon参数的分配失败的并发标识verbosegc输出。第3行的State为0，表示并发标识的状态为HALTED。第4行表示清理了多少卡片。

4.8.10 并发标识的verbosegc输出

<CON[41]: Concurrent collection, (284528/8238832) (17560/17168), 874 ms since last CON or AF>

<GC(45): Bytes Traced =5098693 (Foreground: 555297+ Background: 4543396) State = 2 >

<GC(45): GC cycle started Tue Oct 08 12:31:14 2002

<GC(45): freed 2185000 bytes, 30% free (2487088/8256000), in 7 ms>

<GC(45): mark: 5 ms, sweep: 2 ms, compact: 0 ms>

<GC(45): refs: soft 0 (age >= 32), weak 0, final 0, phantom 0>

<CON[41]: completed in 9 ms>

图表 22 并发标识的verbosegc输出

图表12是由并发标识开始的一个垃圾收集周期的verbosegc输出，和分配失败并发标识的verbosegc输出非常相似，只是在最后一行中由“CON”取代了原来的“AF”。在本例中，State为2，表示后台线程已经没有更多的工作需要处理了。

4.8.11 带有:Xgccon参数的并发标识的verbosegc输出

<CON[20]: Concurrent collection, (397808/131070464) (3145728/3145728), 5933 ms since last CON or AF>

<GC(26): Bytes Traced =11845976 (Foreground: 4203037+ Background: 7642939) State = 1 >

<GC(26): Card Cleaning Done. Cleaned:4127 (0 skipped). Estimation 3896 (Factor 0.015)>

<GC(26): GC cycle started Fri Oct 11 09:45:32 2002

<GC(26): wait for concurrent tracers: 1 ms>

<GC(26): freed 117639824 bytes, 90% free (121183360/134216192), in 20 ms>

<GC(26): mark: 10 ms, sweep: 10 ms, compact: 0 ms>

<GC(26): In mark: Final dirty Cards scan: 838 cards

<GC(26): refs: soft 0 (age >= 32), weak 0, final 0, phantom 0>

<CON[20]: completed in 21 ms>

图表 23带有:Xgccon参数的并发标识的verbosegc输出

图表23是带有:Xgccon参数的并发标识的verbosegc输出，类似分配失败的垃圾收集，带有追踪字节数以及清理的卡片数量信息。第5行显示等待并发追踪完成的时间。

4.8.12 verbosegc和Resettable

<TH_AF[8]: Transient heap Allocation Failure. need 64 bytes, 9716 ms since last TH_AF>

<TH_AF[8]: managing TH allocation failure, action=3 (0/4389888)>

<GC(25): need to expand transient mark bits for 4586496-byte heap>

<GC(25): expanded transient mark bits by 3072 to 71672 bytes>

<GC(25): need to expand transient alloc bits for 4586496-byte heap>

<GC(25): expanded transient alloc bits by 3072 to 71672 bytes>

<GC(25): expanded transient heap fully by 196608 to 4586496 bytes>

<TH_AF[8]: completed in 1 ms>

图表 24 临时堆空间分配失败的verbosegc输出

对于Resettable的虚拟机，有一个中间件堆（middleware heap）和一个临时堆（transient heap）。在临时堆的verbosegc稍有不同，图表24就是一个示例输出。注意，在这里，TH_AF取代了AF标识。resettable虚拟机中发生分配失败时，会扩展临时堆空间，而不是进行垃圾收集。图表24是临时堆扩展成功的输出示例。

<TH_AF[11]: Transient heap Allocation Failure. need 32 bytes, 16570 ms since last TH_AF>

<TH_AF[11]: managing TH allocation failure, action=3 (0/4586496)>

<TH_AF[11]: managing TH allocation failure, action=2 (0/4586496)>

<GC(29): GC cycle started Tue Mar 19 14:47:42 2002

<GC(29): freed 402552 bytes from Transient Heap 8% free (402552/4586496) and...>

<GC(29): freed 1456 bytes, 38% free (623304/1636864), in 1285 ms>

<GC(29): mark: 1263 ms, sweep: 22 ms, compact: 0 ms>

<GC(29): refs: soft 0 (age >= 6), weak 0, final 0, phantom 0>

<TH_AF[11]: completed in 1287 ms>

图表 25 临时堆扩展失败的verbosegc输出

图表25是临时堆扩展失败的verbosegc输出，此时必须进行垃圾收集。在输出中包含了中间件堆中和临时堆中分别释放的空间。

5 消息

本章是IBM JVM错误信息描述，请参考原文。

6 命令行参数

下面是虚拟机内存储分配以及垃圾收集相关的命令行参数

-verbosegc

-verbose:gc

显示垃圾收集的信息。在不同的版本，不同的平台的具体输出格式不同。

-verbose:Xgccon

显示垃圾收集信息。除了-verbosegc参数的输出之外，还包含卡片清理的信息。只有在-Xgcpolicy参数为optavgpause时才可以使用本参数。

-Xverbosegclog:<path to file><file name>

将verbosegc的输出重定向到一个文件。如果找不到所指定的路径，则输出到stderr中。

-Xverbosegclog:<path to file><file name, X, Y>

文件名中必须包含一个“#”，从1开始，在实际输出时会用数字替代“#”

X和Y是一个整数数值。表示verbosegc的输出保存到Y个文件中，每个文件包含X次垃圾收集周期。

注：从1.4.1开始，环境变量IBM_JVMST_VERBOSEGC_LOG不再被使用。

-Xcompactgc

每次垃圾收集都进行压缩。默认是false

-Xdisableexplicitgc

禁用由Sytem.gc()调用引起的垃圾收集。很多应用代码中都存在调用System.gc()的情况。这样会由于不合时宜的垃圾收集导致应用性能下降。如果从应用中删除这些代码不方便的话，可以使用本参数来通知虚拟机，对于应用调用System.gc()不进行真正的垃圾收集。

如果测试发现-Xdisableexplicitgc对于应用性能有所改善，建议使用在生产环境中。在以下场景，不要设置本参数：

· 带有CICS参数的zSeries虚拟机，运行在resettable模式，或者是运行DB/2存过过程的

· 某些性能分析工具通过显式的垃圾收集分析释放的对象或者检测内存泄漏问题的

· 性能基准测试中，需要在两轮测试场景之间进行显式垃圾收集的

-Xgcpolicy:<optthruput|optavgpause>

设置-Xgcpolicy为optthruput，就会禁用并发标识能力。此为默认设置。对于垃圾收集暂停时间可以接受的应用，optthruput可以带来最好的吞吐量。

设置-Xgcpolicy为optavgpause启用并发标识。对于垃圾收集导致的响应慢的应用可以使用optavgpause。

-Xgcthreads

设置用来进行垃圾收集的全部线程的数量。在一个有N个处理器的平台上，如果虚拟机运行于resettable模式，本参数默认为1；如果不是resettable模式，则为N。

-Xinitacsh<size>

设置存放应用类的系统堆初始大小。只适用于resettable虚拟机。

-Xinitsh<size>

设置系统堆的初始大小。只适用于resettable虚拟机。

-Xjvmset<size>

创建主虚拟机（Master JVM）。设置共享内存的大小，单位为MB。默认是1MB。当JNI_CreateJavaVM()函数返回成功之后，JavaVMOption的”extrainfo”字段会传传递工作虚拟机。

当启动主虚拟机时，必须将-Xresettable参数和本参数一起使用。

-Xjvmset

创建工作虚拟机（Worker JVM）。JavaVMOption的”extrainfo”字段中包含了创建主虚拟机时的-Xjvmset参数。

-Xmaxe<size>

设置堆的最大扩展量，默认值为0。在resettable模式下，对于中间件堆和临时堆，实际的最大扩展量为<size>/2。

-Xmaxf<number>

0到1之间的一个浮点数，用来设置堆的最大空闲率，默认值是0.6，即60%。如果本参数设置为0，堆会保持收缩；如果设置为1，堆永不收缩。在resettable模式下，本参数仅用于中间件堆。

-Xmine<size>

设置堆的最小扩展量。默认值为1MB。在resettable模式下，对于中间件堆和临时堆，实际的最小扩展量为<size>/2。

-Xminf<number>

0到1之间的一个浮点数，用来设置堆的最小空闲率，默认值是0.3，即30%。如果堆内空闲率小于本参数设置，则堆会进行扩展。在resettable模式下，本参数用于中间件堆和临时堆。

-Xms<size>

堆的初始大小。默认值为：

· Windows, AIX, Linux：4MB

· OS/390：1MB

-Xmx<size>

堆的最大大小。在resettable模式下，本参数决定了中间件堆和临时堆总共的大小，中间件堆从底开始增长，临时堆从顶开始增长。如果未明确指定，默认值为：

· Windows：物理内存的一半，最小16MB，最大2GB-1

· OS/390, AIX：64MB

· Linux：物理内存的一半，最小16MB，最大512MB-1

-Xnocompactgc

禁用堆压缩。默认值为false。

-Xnopartialcompactgc

禁用增量压缩。默认值为false。

-Xpartialcompactgc

每次垃圾收集都运行增量压缩。默认值为false。

-Xresettable

设置支持resettable模式。

原文 翻译

reachable 可到达的

heap lock 堆锁

JVM 虚拟机

heap 堆

stack 栈

bit 比特位

byte 字节

word 字

thread local heap 线程本地堆

garbage collector 垃圾收集器

garbage collection 垃圾收集

frame 帧

storage component 存储组件

pinned cluster 固化簇

critical lock 临界锁

allocbits 分配集合

markbits 标识集合

compact 压缩

system heap 系统堆

dark matter 暗物质

bitwise sweep 按位清理

wilderness 荒地

transient heap 临时堆