在生产环境中执行的应用程序当出现响应时间慢以及过于频繁的GC,那么此时就需要收集JVM运行的数据来分析是什么原因导致了应用程序响应时间慢,也许在这个过程中出现了大量的文件I/O加载导致都有可能导致程序出现内存泄露等情况。特别是在企业级的生产环境中,在出现问题的时候很难使用主流的可视化工具来查看JVM运行过程中的数据,此时可以使用jstat命令工具来收集JVM运行过程中的数据,下面详细地阐述jstat命令行工具的案例应用与实战。
jstat全称为JVM Statistics Monitoring Tool,它主要用于收集JVM在执行过程中运行的各种数据,如垃圾收集,GC次数以及YGC、YGCT等数据。jstat是一个命令行的工具,下面汇总了jstat命令行使用过程中常用到的选项,具体如下所示。
- -gc:监视JAVA的堆情况,包含了老年代、新生代、GC次数&时间等
- gcnew:监视新生代GC状况
- -gcold:监视老生代GC状况
- -gcutil:输出的内容与“-gc”基本一致,重点关注已使用空间占总空间的百分比
- -class:监视类装、卸载数量、总空间、类装载所消耗费的时间
jstat案例实战
在案例代码中编写了不断的加载对象,持续的进行最终会导致程序出现内存泄露,涉及到的案例代码如下。
代码语言:javascript复制import java.util.ArrayList;
import java.util.List;
import java.util.UUID;
@RestController
public class HeapController
{
@RequestMapping("/heap")
public void heap ()
{
List<Person> lists=new ArrayList<Person>();
while (true)
{
int i=0;
lists.add(new Person(i ,UUID.randomUUID().toString()));
}
}
}
启动应用程序,逐步地演示下上面阐述到的各个命令行选项工具的应用。首先来看“-class”中需要输出的信息,每隔1秒打印一次并且加上时间戳,打印10次,每5行输出表头信息,执行命令以及输出的结果信息如下:
代码语言:javascript复制localhost:~ $ jps
48199 Jps
48143 DbPlusApplication
localhost:~ $ jstat -class -t -h5 48143 1000 10
Timestamp Loaded Bytes Unloaded Bytes Time
146.6 8356 15240.6 0 0.0 3.09
147.6 8356 15240.6 0 0.0 3.09
148.6 8356 15240.6 0 0.0 3.09
149.6 8601 15672.1 43 58.6 3.23
150.6 8601 15672.1 43 58.6 3.23
Timestamp Loaded Bytes Unloaded Bytes Time
151.6 8601 15672.1 43 58.6 3.23
152.6 8752 15925.3 43 58.6 3.33
153.6 8771 15948.6 43 58.6 3.33
154.6 8771 15948.6 43 58.6 3.33
155.6 8771 15948.6 43 58.6 3.33
备注:如上可以看到类装载、卸载数量、装载耗时都是呈上升的趋势。
下面再演示下可能出现内存泄露的情况下新生代指标的变化趋势,执行命令以及输出结果信息如下:
代码语言:javascript复制localhost:~ $ jps
48354 DbPlusApplication
48367 Jps
localhost:~ $ jstat -gcnew -t -h5 48354 1000 10
Timestamp S0C S1C S0U S1U TT MTT DSS EC EU YGC YGCT
50.1 2048.0 2048.0 0.0 584.8 1 15 2048.0 6656.0 1738.5 65 0.121
51.1 2048.0 2048.0 0.0 584.8 1 15 2048.0 6656.0 1789.4 65 0.121
52.1 2048.0 2048.0 0.0 950.9 1 15 2048.0 6656.0 0.0 69 0.133
53.2 2048.0 2048.0 0.0 0.0 1 15 2048.0 6656.0 6656.0 75 0.146
54.2 2048.0 2048.0 0.0 0.0 1 15 2048.0 6656.0 6656.0 75 0.146
Timestamp S0C S1C S0U S1U TT MTT DSS EC EU YGC YGCT
55.2 2048.0 2048.0 0.0 0.0 1 15 2048.0 6656.0 6656.0 75 0.146
56.2 2048.0 1536.0 1089.8 0.0 2 15 1536.0 7168.0 6184.5 76 0.149
57.2 2048.0 1536.0 1089.8 0.0 2 15 1536.0 7168.0 6527.5 76 0.149
58.2 2048.0 1536.0 1089.8 0.0 2 15 1536.0 7168.0 6601.6 76 0.149
59.2 2048.0 1536.0 1089.8 0.0 2 15 1536.0 7168.0 6665.8 77 0.149
备注:如上输出信息中,可以看到新生代空间EU从1738.5一直上升到6665.8,YGC的次数最多是77,YGCT耗时时间从0.121s一直上升到0.149s。
如下演示可能出现内存泄露的情况下老年代指标变化的趋势过程,执行的命令以及输出的结果信息如下:
代码语言:javascript复制localhost:~ $ jps
48518 DbPlusApplication
48523 Jps
localhost:~ $ jstat -gcold -t -h5 48518 1000 15
Timestamp MC MU CCSC CCSU OC OU YGC FGC FGCT GCT
31.0 46168.0 43040.7 6272.0 5611.1 22016.0 19029.5 65 2 0.081 0.235
32.1 46168.0 43040.7 6272.0 5611.1 22016.0 19029.5 65 2 0.081 0.235
33.1 46168.0 43040.7 6272.0 5611.1 22016.0 19029.5 65 2 0.081 0.235
34.1 46168.0 43040.7 6272.0 5611.1 22016.0 19029.5 65 2 0.081 0.235
35.0 47576.0 44156.6 6400.0 5750.3 22016.0 21703.9 75 16 0.813 1.000
Timestamp MC MU CCSC CCSU OC OU YGC FGC FGCT GCT
36.0 47576.0 44156.8 6400.0 5750.3 22016.0 21703.6 75 36 1.805 1.992
37.1 47576.0 44156.9 6400.0 5750.3 22016.0 21703.6 75 55 2.769 2.956
38.1 47832.0 44645.1 6400.0 5818.2 22016.0 15092.8 76 57 3.009 3.198
39.1 48728.0 45331.7 6528.0 5905.2 22016.0 21948.4 86 71 3.724 3.934
40.1 48728.0 45331.7 6528.0 5905.2 22016.0 21670.1 86 94 4.744 4.954
Timestamp MC MU CCSC CCSU OC OU YGC FGC FGCT GCT
41.1 48728.0 45333.8 6528.0 5905.8 22016.0 21670.1 86 116 5.721 5.931
42.1 48728.0 45333.8 6528.0 5905.8 22016.0 15336.1 86 120 5.951 6.161
43.1 48728.0 45343.0 6528.0 5905.8 22016.0 21711.1 98 137 6.692 6.926
44.1 48728.0 45343.0 6528.0 5905.8 22016.0 21710.9 98 160 7.723 7.957
45.1 48728.0 45343.0 6528.0 5905.8 22016.0 15346.2 98 176 8.434 8.669
备注:在如上可以看到OU的变化趋势是上升到21711.1最后是下降的趋势,而YGC、FGC的次数一直是上升的趋势,FGCT、GCT的耗时也是上升的趋势,其中GCT的总耗时最大是8.669s。
判断是否内存泄露
在jstat命令行工具中可以根据如下的思路来判断是否可能出现了内存泄露,具体思路如下:
- 运行中的Java程序,运行jstat命令行工具获取JVM运行的数据,重点关注OU值的数据(OU:老年代目前已使用空间)
- 重复如上的操作,如果OU的值呈上升的趋势,说明Java程序的老年代内存已使用量在不断上涨,那么也就意味着无法回收的对象在不断的增加,很有可能存在内存泄露。
根据如上的思路,下面调用应用程序的不同接口,关注所有的GC指标,执行的命令以及输出的值信息如下
代码语言:javascript复制localhost:~ $ jps
49066 DbPlusApplication
49083 Jps
localhost:~ $ jstat -gc -t -h5 49066 1000 30
Timestamp S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT
33.4 2560.0 2560.0 608.0 0.0 5632.0 4355.3 22016.0 19491.3 45904.0 42710.0 6224.0 5572.1 64 0.186 2 0.108 0.294
34.4 2560.0 2560.0 608.0 0.0 5632.0 4468.2 22016.0 19491.3 45904.0 42710.0 6224.0 5572.1 64 0.186 2 0.108 0.294
35.4 2560.0 2560.0 608.0 0.0 5632.0 4524.6 22016.0 19491.3 45904.0 42710.0 6224.0 5572.1 64 0.186 2 0.108 0.294
36.4 2560.0 2560.0 608.0 0.0 5632.0 4637.4 22016.0 19491.3 45904.0 42710.0 6224.0 5572.1 64 0.186 2 0.108 0.294
37.4 2560.0 2560.0 608.0 0.0 5632.0 4694.1 22016.0 19491.3 45904.0 42710.0 6224.0 5572.1 64 0.186 2 0.108 0.294
Timestamp S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT
38.4 2048.0 2048.0 0.0 1113.9 6656.0 2269.6 22016.0 20336.9 47952.0 44524.5 6480.0 5821.6 67 0.198 2 0.108 0.305
39.4 2048.0 2048.0 0.0 1113.9 6656.0 2354.7 22016.0 20336.9 47952.0 44524.5 6480.0 5821.6 67 0.198 2 0.108 0.305
40.4 2048.0 2048.0 1118.5 0.0 6656.0 726.2 22016.0 20800.9 48720.0 45417.2 6480.0 5915.8 68 0.200 2 0.108 0.308
41.4 2048.0 2048.0 1118.5 0.0 6656.0 1594.6 22016.0 20800.9 48720.0 45417.2 6480.0 5915.8 68 0.200 2 0.108 0.308
42.4 2048.0 2048.0 0.0 0.0 6656.0 698.4 22016.0 16514.3 49360.0 46074.2 6608.0 5989.8 69 0.204 3 0.215 0.418
Timestamp S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT
43.4 2048.0 2048.0 0.0 985.3 6656.0 0.0 22016.0 20549.8 49360.0 46117.1 6608.0 5995.6 75 0.230 3 0.215 0.445
44.4 2048.0 2048.0 0.0 0.0 6656.0 5995.1 22016.0 21668.7 49360.0 46110.1 6608.0 5994.5 76 0.236 20 1.133 1.369
45.4 2048.0 2048.0 0.0 0.0 6656.0 6624.6 22016.0 21576.5 49360.0 46110.1 6608.0 5994.5 76 0.236 39 2.139 2.376
46.4 2048.0 2048.0 0.0 0.0 6656.0 6652.9 22016.0 21525.2 49360.0 46110.1 6608.0 5994.5 76 0.236 58 3.157 3.393
47.4 2048.0 2048.0 0.0 0.0 6656.0 6656.0 22016.0 21525.7 49360.0 46110.1 6608.0 5994.5 76 0.236 77 4.113 4.349
Timestamp S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT
48.4 2048.0 2048.0 0.0 0.0 6656.0 6656.0 22016.0 21528.9 49360.0 46110.1 6608.0 5994.5 76 0.236 97 5.120 5.356
49.5 2048.0 2048.0 0.0 0.0 6656.0 6656.0 22016.0 21532.5 49360.0 46110.4 6608.0 5994.5 76 0.236 116 6.105 6.341
50.5 2048.0 2048.0 0.0 0.0 6656.0 6656.0 22016.0 21538.4 49360.0 46110.4 6608.0 5994.5 76 0.236 136 7.124 7.360
51.4 2048.0 2048.0 0.0 0.0 6656.0 6656.0 22016.0 21540.8 49360.0 46110.4 6608.0 5994.5 76 0.236 156 8.141 8.377
52.4 2048.0 2048.0 0.0 0.0 6656.0 6656.0 22016.0 21548.3 49360.0 46110.4 6608.0 5994.5 76 0.236 175 9.101 9.337
Timestamp S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT
53.4 2048.0 2048.0 0.0 0.0 6656.0 6656.0 22016.0 21558.3 49360.0 46110.4 6608.0 5994.5 76 0.236 195 10.106 10.342
54.4 2048.0 2048.0 0.0 0.0 6656.0 6656.0 22016.0 21566.5 49360.0 46110.7 6608.0 5994.5 76 0.236 215 11.110 11.346
55.5 2048.0 2048.0 0.0 0.0 6656.0 6656.0 22016.0 21572.2 49360.0 46111.4 6608.0 5994.5 76 0.236 235 12.134 12.370
56.5 2048.0 2048.0 0.0 0.0 6656.0 6656.0 22016.0 21575.0 49360.0 46111.8 6608.0 5994.5 76 0.236 255 13.137 13.374
57.4 2048.0 2048.0 0.0 0.0 6656.0 6655.8 22016.0 21571.3 49360.0 46113.0 6608.0 5994.5 76 0.236 274 14.102 14.338
Timestamp S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT
58.5 2048.0 2048.0 0.0 0.0 6656.0 6656.0 22016.0 21578.2 49360.0 46114.4 6608.0 5994.5 76 0.236 294 15.112 15.348
59.5 2048.0 2048.0 0.0 0.0 6656.0 4720.5 22016.0 15587.7 49616.0 46116.6 6608.0 5994.5 76 0.236 309 15.962 16.198
60.5 2048.0 2048.0 0.0 0.0 6656.0 4790.8 22016.0 15587.7 49616.0 46116.6 6608.0 5994.5 76 0.236 309 15.962 16.198
61.5 2048.0 2048.0 0.0 0.0 6656.0 4855.1 22016.0 15587.7 49616.0 46116.6 6608.0 5994.5 76 0.236 309 15.962 16.198
62.5 2048.0 2048.0 0.0 0.0 6656.0 4921.3 22016.0 15587.7 49616.0 46116.6 6608.0 5994.5 76 0.236 309 15.962 16.198
备注:在如上中依据每5行输出一次表头信息,而OU的值分别是:19491.3、20336.9、20549.8、21528.9、21558.3、21578.2,可以看到OU的值呈上升的趋势,根据之前的判断思路程序很有可能出现内存泄露,程序端运行错误确实显示了内存泄露的错误信息,具体为:java.lang.OutOfMemoryError: Java heap space。在上面的数据中也可以看到YGC、FGC都在上升,特别是FGC从2一直上升到了309,变化趋势很大,对应的FGCT它的耗时也是从0.108一直到最后的15.962,而YGC、YGCT有变化趋势但是不是那么很明显。FGCT耗时拉高了整体的GCT的耗时,总耗时最后是16.198,等于FGCT占用了总耗时的98.54%。因此在工作中当程序很有可能内存泄露的时候重点关注OU的值,以及对应的FGC次数、FGCT耗时情况。