JVM深入理解-内存调优与GC日志

发表于 | 更新于: | 分类于
CPU飚高分析

一般可以使用

  • ps -Lfp pid
  • ps -mp pid -o THREAD, tid, time
  • top -Hp pid
1
2
3
4
5
6
7
8
9
10
[root@redis webapps]# top -Hp 22272
top - 10:09:30 up 9 days, 22:10,  1 user,  load average: 0.00, 0.00, 0.00
Tasks:  30 total,   0 running,  30 sleeping,   0 stopped,   0 zombie
Cpu(s):  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:   3923196k total,  3795588k used,   127608k free,   153056k buffers
Swap:  6160376k total,        0k used,  6160376k free,  3079244k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                                                
22272 root      20   0 2286m 122m  11m S  0.0  3.2   0:00.00 java                                                                                                                                                    
22278 root      20   0 2286m 122m  11m S  0.0  3.2   0:00.00 java

TIME列就是各个Java线程耗费的CPU时间，CPU时间最长的是线程ID为22283 的线程。

用 printf "%x\n" 22283

1
2
[root@redis webapps]# printf ‘%x\n’ 22283
570b得到22283 的十六进制值为570b。

下一步轮到jstack上场了，它用来输出进程22272 的堆栈信息，然后根据线程ID的十六进制值grep，如下：

1
2
[root@redis webapps]# jstack 22272 | grep 570b
“SchedulerThread” prio=10 tid=0x00007f950043e000 nid=0x54ee in Object.wait()

可以看到CPU消耗在SchedulerThread这个类的Object.wait()，定位到下面的代码：

1
2
3
4
5
6
7
8
9
10
// Idle wait
synchronized(sigLock) {
  try {
    if(!halted.get()) {
      sigLock.wait(timeUntilContinue);
    }
  } 
  catch (InterruptedException ignore) {
  }
}

它是轮询任务的空闲等待代码，上面的sigLock.wait(timeUntilContinue)就对应了前面的Object.wait()。

总结：可以通过PID找到对应的的线程，然后通过JVM的jstack找到栈里对应的线程信息。通过找到对应的代码一般就能分析出CPU占用高的原因。

利用JVM命令分析

jstat -gcutil
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
[root@xxxx-nccz8-b57dd64fc-nt9dj logs]# jstat -gcutil 1 2000 20
S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT   
  0.00   8.64   2.62  27.32  80.59  73.86   1350   22.705     5    1.449   24.154
  0.00   8.64   2.81  27.32  80.59  73.86   1350   22.705     5    1.449   24.154
  0.00   8.64   2.81  27.32  80.59  73.86   1350   22.705     5    1.449   24.154
  0.00   8.64   2.81  27.32  80.59  73.86   1350   22.705     5    1.449   24.154
  0.00   8.64   3.06  27.32  80.59  73.86   1350   22.705     5    1.449   24.154
  0.00   8.64   3.10  27.32  80.59  73.86   1350   22.705     5    1.449   24.154
  0.00   8.64   3.10  27.32  80.59  73.86   1350   22.705     5    1.449   24.154
  0.00   8.64   3.21  27.32  80.59  73.86   1350   22.705     5    1.449   24.154
  0.00   8.64   3.22  27.32  80.59  73.86   1350   22.705     5    1.449   24.154
  0.00   8.64   3.61  27.32  80.59  73.86   1350   22.705     5    1.449   24.154
  0.00   8.64   6.47  27.32  80.59  73.86   1350   22.705     5    1.449   24.154
  0.00   8.64   6.76  27.32  80.59  73.86   1350   22.705     5    1.449   24.154
  0.00   8.64   6.81  27.32  80.59  73.86   1350   22.705     5    1.449   24.154
  0.00   8.64   7.07  27.32  80.59  73.86   1350   22.705     5    1.449   24.154
  0.00   8.64   7.08  27.32  80.59  73.86   1350   22.705     5    1.449   24.154
  0.00   8.64   7.38  27.32  80.59  73.86   1350   22.705     5    1.449   24.154
  0.00   8.64   7.38  27.32  80.59  73.86   1350   22.705     5    1.449   24.154
  0.00   8.64   7.62  27.32  80.59  73.86   1350   22.705     5    1.449   24.154
  0.00   8.64   7.62  27.32  80.59  73.86   1350   22.705     5    1.449   24.154
  0.00   8.64   7.76  27.32  80.59  73.86   1350   22.705     5    1.449   24.154

S0：Heap上的 Survivor space 0 区已使用空间的百分比
S1：Heap上的 Survivor space 1 区已使用空间的百分比
E：Heap上的 Eden space 区已使用空间的百分比
O：Heap上的 Old space 区已使用空间的百分比
M：Metaspace 区已使用空间的百分比
YGC：从应用程序启动到采样时发生 Young GC 的次数
YGCT：从应用程序启动到采样时 Young GC 所用的时间(单位秒)
FGC：从应用程序启动到采样时发生 Full GC 的次数
FGCT：从应用程序启动到采样时 Full GC 所用的时间(单位秒)
GCT：从应用程序启动到采样时用于垃圾回收的总时间(单位秒)

jmap -heap
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
[root@xxxx-nccz8-b57dd64fc-nt9dj startup]# jmap -heap 1
Attaching to process ID 1, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.191-b12

using parallel threads in the new generation.
using thread-local object allocation.
Concurrent Mark-Sweep GC

Heap Configuration:
   MinHeapFreeRatio         = 40
   MaxHeapFreeRatio         = 70
   MaxHeapSize              = 2147483648 (2048.0MB)
   NewSize                  = 805306368 (768.0MB)
   MaxNewSize               = 805306368 (768.0MB)
   OldSize                  = 1342177280 (1280.0MB)
   NewRatio                 = 2
   SurvivorRatio            = 8
   MetaspaceSize            = 268435456 (256.0MB)
   CompressedClassSpaceSize = 260046848 (248.0MB)
   MaxMetaspaceSize         = 268435456 (256.0MB)
   G1HeapRegionSize         = 0 (0.0MB)

Heap Usage:
New Generation (Eden + 1 Survivor Space):
   capacity = 724828160 (691.25MB)
   used     = 284988360 (271.7860794067383MB)
   free     = 439839800 (419.4639205932617MB)
   39.318058503687276% used
Eden Space:
   capacity = 644349952 (614.5MB)
   used     = 275398000 (262.63999938964844MB)
   free     = 368951952 (351.86000061035156MB)
   42.74043928228616% used
From Space:
   capacity = 80478208 (76.75MB)
   used     = 9590360 (9.146080017089844MB)
   free     = 70887848 (67.60391998291016MB)
   11.916716634644748% used
To Space:
   capacity = 80478208 (76.75MB)
   used     = 0 (0.0MB)
   free     = 80478208 (76.75MB)
   0.0% used
concurrent mark-sweep generation:
   capacity = 1342177280 (1280.0MB)

通过heap命令能看出当前整个堆的一个使用情况，used与free的一个实际占用比。

jmap -dump
1
jmap -dump:live,format=b,file=xxxxxx.20200707.hprof 1

我们一般会在Dockerfile里面配置好如果出现OOM的情况，保留一下现场。-XX:HeapDumpPath=/alidata1/admin/xxxxx/logs

利用JProfiler分析

发现大对象，这里是因为我们用了Jeager链路跟踪，但是用过多线程导致ThreadLocal没有释放掉。

http://static.cyblogs.com/QQ20200507-183901@2x.jpg

发现char[]占用比较多，并且找出是从哪儿产生的？

http://static.cyblogs.com/QQ20200507-194442@2x.jpg

通过Outgoing references找到具体的实例情况。

http://static.cyblogs.com/QQ20200507-194529@2x.jpg

什么是outgoing references与incoming references？让我们通过示例来了解有关 Incoming references 和 Outgoing references 的更多知识。例如，一个应用程序的源代码如下所示：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
public class A {     
  private C c1 = C.getInstance();
}

public class B {     
	private C c2 = C.getInstance();
}

public class C {     
	private static C myC = new C();     

	public static C getInstance() {             
	return myC;     
	}   

	private D d1 = new D();     
	private E e1 = new E();
}

public class D {
}

public class E {
}

public class SimpleExample {     
	public static void main (String argsp[]) throws Exception {
           A a = new A();
           B b = new B();     
    }
}
  • 对象 A 和对象 B 持有对象 C 的引用
  • 对象 C 持有对象 D 和对象 E 的引用

在这个示例项目中，让我们具体分析下对象 C 的 Incoming references 和 Outgoing references 。

对象 C 的 Incoming References

拥有对象 C 的引用的所有对象都称为 Incoming references。在此示例中，对象 C 的“Incoming references”是对象 A、对象 B 和 C 的类对象 。

对象 C 的 Outgoing References

对象 C 引用的所有对象都称为 Outgoing References。在此示例中，对象 C 的“outgoing references”是对象 D、对象 E 和 C 的类对象。

然后通过Show in graph的菜单，一层一层的点击。直到你看到你最熟悉的类。

http://static.cyblogs.com/WechatIMG459.png

http://static.cyblogs.com/WechatIMG460.png

如何看GC日志

设置gc日志配置

1
2
3
4
5
6
7
8
-XX:+PrintGC 输出简要GC日志 
-XX:+PrintGCDetails 输出详细GC日志 
-Xloggc:gc.log  输出GC日志到文件
-XX:+PrintGCTimeStamps 输出GC的时间戳（以JVM启动到当期的总时长的时间戳形式） 
-XX:+PrintGCDateStamps 输出GC的时间戳（以日期的形式，如 2013-05-04T21:53:59.234+0800） 
-XX:+PrintHeapAtGC 在进行GC的前后打印出堆的信息
-verbose:gc
-XX:+PrintReferenceGC 打印年轻代各个引用的数量以及时长
-XX:+PrintGC

如果只设置-XX:+PrintGC那么打印的日志如下所示：

1
2
3
4
5
6
7
8
[GC (Allocation Failure)  61805K->9849K(256000K), 0.0041139 secs]

1、GC 表示是一次YGC（Young GC）
2、Allocation Failure 表示是失败的类型
3、61805K->9849K 表示年轻代从61805K降为9849K
4、256000K表示整个堆的大小
5、0.0041139 secs表示这次GC总计所用的时间
在JDK 8中，-verbose:gc是-XX:+PrintGC一个别称，日志格式等价与：-XX:+PrintGC，。
-XX:+PrintGCDetails
1
2
3
4
5
6
7
8
9
10
11
[GC (Allocation Failure) [PSYoungGen: 53248K->2176K(59392K)] 58161K->7161K(256000K), 0.0039189 secs] [Times: user=0.02 sys=0.01, real=0.00 secs]
1、GC 表示是一次YGC（Young GC）
2、Allocation Failure 表示是失败的类型
3、PSYoungGen 表示年轻代大小
4、53248K->2176K 表示年轻代占用从53248K降为2176K
5、59392K表示年轻带的大小
6、58161K->7161K 表示整个堆占用从53248K降为2176K
7、256000K表示整个堆的大小
8、 0.0039189 secs 表示这次GC总计所用的时间
9、[Times: user=0.02 sys=0.01, real=0.00 secs]  分别表示，用户态占用时长，内核用时，真实用时。
时间保留两位小数，四舍五入。
-XX:+PrintGCTimeStamps
1
1.963: [GC (Allocation Failure)  61805K->9849K(256000K), 0.0041139 secs]

如果加上-XX:+PrintGCTimeStamps那么日志仅仅比1.1介绍的最前面多了一个时间戳： 1.963， 表示从JVM启动到打印GC时刻用了1.963秒。

-XX:+PrintGCDateStamps
1
2019-03-05T16:56:15.108+0800: [GC (Allocation Failure)  61805K->9849K(256000K), 0.0041139 secs]

如果加上-XX:+PrintGCDateStamps那么日志仅仅比1.1介绍的最前面多了一个日期时间： 2019-03-05T16:56:15.108+0800， 表示打印GC的时刻的时间是2019-03-05T16:56:15.108+0800。+0800表示是东8区。

CMS GC日志详细分析
1
2
3
4
5
6
7
8
9
10
11
12
[GC (CMS Initial Mark) [1 CMS-initial-mark: 19498K(32768K)] 36184K(62272K), 0.0018083 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[CMS-concurrent-mark-start]
[CMS-concurrent-mark: 0.011/0.011 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
[CMS-concurrent-preclean-start]
[CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time [CMS-concurrent-abortable-preclean: 0.558/5.093 secs] [Times: user=0.57 sys=0.00, real=5.09 secs] 
[GC (CMS Final Remark) [YG occupancy: 16817 K (29504 K)][Rescan (parallel) , 0.0021918 secs][weak refs processing, 0.0000245 secs][class unloading, 0.0044098 secs][scrub symbol table, 0.0029752 secs][scrub string table, 0.0006820 secs][1 CMS-remark: 19498K(32768K)] 36316K(62272K), 0.0104997 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
[CMS-concurrent-sweep-start]
[CMS-concurrent-sweep: 0.007/0.007 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[CMS-concurrent-reset-start]
[CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

CMS日志分为两个STW(stop the world)

分别是init remark（1） 与 remark（7）两个阶段。一般耗时比YGC长约10倍（个人经验）。

（1）、[GC (CMS Initial Mark) [1 CMS-initial-mark: 19498K(32768K)] 36184K(62272K), 0.0018083 secs][Times: user=0.01 sys=0.00, real=0.01 secs]

会STW(Stop The World)，这时候的老年代容量为 32768K， 在使用到 19498K 时开始初始化标记。耗时短。

（2）、[CMS-concurrent-mark-start]

并发标记阶段开始

（3）、[CMS-concurrent-mark: 0.011/0.011 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]

并发标记阶段花费时间。

（4）、[CMS-concurrent-preclean-start]

并发预清理阶段，也是与用户线程并发执行。虚拟机查找在执行并发标记阶段新进入老年代的对象(可能会有一些对象从新生代晋升到老年代， 或者有一些对象被分配到老年代)。通过重新扫描，减少下一个阶段”重新标记”的工作，因为下一个阶段会Stop The World。

（5）、[CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

并发预清理阶段花费时间。

（6）、[CMS-concurrent-abortable-preclean-start] CMS: abort preclean due to time [CMS-concurrent-abortable-preclean: 0.558/5.093 secs][Times: user=0.57 sys=0.00, real=5.09 secs]

并发可中止预清理阶段，运行在并行预清理和重新标记之间，直到获得所期望的eden空间占用率。增加这个阶段是为了避免在重新标记阶段后紧跟着发生一次垃圾清除

（7）、[GC (CMS Final Remark) [YG occupancy: 16817 K (29504 K)][Rescan (parallel) , 0.0021918 secs][weak refs processing, 0.0000245 secs][class unloading, 0.0044098 secs][scrub symbol table, 0.0029752 secs][scrub string table, 0.0006820 secs][1 CMS-remark: 19498K(32768K)] 36316K(62272K), 0.0104997 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

会STW(Stop The World)，收集阶段，这个阶段会标记老年代全部的存活对象，包括那些在并发标记阶段更改的或者新创建的引用对象

（8）、[CMS-concurrent-sweep-start]

并发清理阶段开始，与用户线程并发执行。

（9）、[CMS-concurrent-sweep: 0.007/0.007 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

并发清理阶段结束，所用的时间。

（10）、[CMS-concurrent-reset-start]

开始并发重置。在这个阶段，与CMS相关数据结构被重新初始化，这样下一个周期可以正常进行。

（11）、[CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

并发重置所用结束，所用的时间。

参考地址

如果大家喜欢我的文章，可以关注个人订阅号。欢迎随时留言、交流。如果想加入微信群的话一起讨论的话，请加管理员简栈文化-小助手（lastpass4u），他会拉你们进群。

简栈文化服务订阅号