我的书签
添加书签
移除书签jstat
jstat 也是标准JDK提供的一款监控工具(Java Virtual Machine statistics monitoring tool),可以统计各种指标。既可以连接到本地JVM,也可以连到远程JVM. 查看支持的指标和对应选项可以执行 “jstat -options” 。例如:
+-----------------+---------------------------------------------------------------+| Option | Displays... |+-----------------+---------------------------------------------------------------+|class | Statistics on the behavior of the class loader ||compiler | Statistics on the behavior of the HotSpot Just-In-Time com- || | piler ||gc | Statistics on the behavior of the garbage collected heap ||gccapacity | Statistics of the capacities of the generations and their || | corresponding spaces. ||gccause | Summary of garbage collection statistics (same as -gcutil), || | with the cause of the last and current (if applicable) || | garbage collection events. ||gcnew | Statistics of the behavior of the new generation. ||gcnewcapacity | Statistics of the sizes of the new generations and its corre- || | sponding spaces. ||gcold | Statistics of the behavior of the old and permanent genera- || | tions. ||gcoldcapacity | Statistics of the sizes of the old generation. ||gcpermcapacity | Statistics of the sizes of the permanent generation. ||gcutil | Summary of garbage collection statistics. ||printcompilation | Summary of garbage collection statistics. |+-----------------+---------------------------------------------------------------+
jstat 对于快速确定GC行为是否健康非常有用。启动方式为: “jstat -gc -t PID 1s” , 其中,PID 就是要监视的Java进程ID。可以通过 jps 命令查看正在运行的Java进程列表。
jpsjstat -gc -t 2428 1s
以上命令的结果, 是 jstat 每秒向标准输出输出一行新内容, 比如:
Timestamp S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT200.0 8448.0 8448.0 8448.0 0.0 67712.0 67712.0 169344.0 169344.0 21248.0 20534.3 3072.0 2807.7 34 0.720 658 133.684 134.404201.0 8448.0 8448.0 8448.0 0.0 67712.0 67712.0 169344.0 169343.2 21248.0 20534.3 3072.0 2807.7 34 0.720 662 134.712 135.432202.0 8448.0 8448.0 8102.5 0.0 67712.0 67598.5 169344.0 169343.6 21248.0 20534.3 3072.0 2807.7 34 0.720 667 135.840 136.559203.0 8448.0 8448.0 8126.3 0.0 67712.0 67702.2 169344.0 169343.6 21248.0 20547.2 3072.0 2807.7 34 0.720 669 136.178 136.898204.0 8448.0 8448.0 8126.3 0.0 67712.0 67702.2 169344.0 169343.6 21248.0 20547.2 3072.0 2807.7 34 0.720 669 136.178 136.898205.0 8448.0 8448.0 8134.6 0.0 67712.0 67712.0 169344.0 169343.5 21248.0 20547.2 3072.0 2807.7 34 0.720 671 136.234 136.954206.0 8448.0 8448.0 8134.6 0.0 67712.0 67712.0 169344.0 169343.5 21248.0 20547.2 3072.0 2807.7 34 0.720 671 136.234 136.954207.0 8448.0 8448.0 8154.8 0.0 67712.0 67712.0 169344.0 169343.5 21248.0 20547.2 3072.0 2807.7 34 0.720 673 136.289 137.009208.0 8448.0 8448.0 8154.8 0.0 67712.0 67712.0 169344.0 169343.5 21248.0 20547.2 3072.0 2807.7 34 0.720 673 136.289 137.009
稍微解释一下上面的内容。参考 jstat manpage , 我们可以知道:
- jstat 连接到 JVM 的时间, 是JVM启动后的 200秒。此信息从第一行的 “Timestamp” 列得知。继续看下一行, jstat 每秒钟从JVM 接收一次信息, 也就是命令行参数中 “
1s“ 的含义。 - 从第一行的 “YGC” 列得知年轻代共执行了34次GC, 由 “FGC” 列得知整个堆内存已经执行了 658次 full GC。
- 年轻代的GC耗时总共为
0.720 秒, 显示在“YGCT” 这一列。 - Full GC 的总计耗时为
133.684 秒, 由“FGCT”列得知。 这立马就吸引了我们的目光, 总的JVM 运行时间只有 200 秒, 但其中有 66% 的部分被 Full GC 消耗了。
再看下一行, 问题就更明显了。
- 在接下来的一秒内共执行了 4 次 Full GC。参见 “FGC“ 列.
- 这4次 Full GC 暂停占用了差不多 1秒的时间(根据 FGCT列的差得知)。与第一行相比, Full GC 耗费了
928 毫秒, 即92.8%的时间。 - 根据 “OC 和 “OU” 列得知, 整个老年代的空间为
169,344.0 KB(“OC“), 在 4 次 Full GC 后依然占用了169,344.2 KB(“OU“)。用了928ms的时间却只释放了 800 字节的内存, 怎么看都觉得很不正常。
只看这两行的内容, 就知道程序出了很严重的问题。继续分析下一行, 可以确定问题依然存在,而且变得更糟。
JVM几乎完全卡住了(stalled), 因为GC占用了90%以上的计算资源。GC之后, 所有的老代空间仍然还在占用。事实上, 程序在一分钟以后就挂了, 抛出了 “java.lang.OutOfMemoryError: GC overhead limit exceeded” 错误。
可以看到, 通过 jstat 能很快发现对JVM健康极为不利的GC行为。一般来说, 只看 jstat 的输出就能快速发现以下问题:
- 最后一列 “GCT”, 与JVM的总运行时间 “Timestamp” 的比值, 就是GC 的开销。如果每一秒内, “GCT“ 的值都会明显增大, 与总运行时间相比, 就暴露出GC开销过大的问题. 不同系统对GC开销有不同的容忍度, 由性能需求决定, 一般来讲, 超过
10%的GC开销都是有问题的。 - “YGC” 和 “FGC” 列的快速变化往往也是有问题的征兆。频繁的GC暂停会累积,并导致更多的线程停顿(stop-the-world pauses), 进而影响吞吐量。
- 如果看到 “OU” 列中,老年代的使用量约等于老年代的最大容量(OC), 并且不降低的话, 就表示虽然执行了老年代GC, 但基本上属于无效GC。
