search

频繁 GC 导致的 Java 服务不响应

hashtag
现象

项目中的某个服务进程是正常的，但是访问这个服务一直返回 Socket Read timeout，最终导致其他服务也受影响。打开服务的日志发现最下面有：

Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "SimplePauseDetectorThread_0" 
 
Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "metrics-logger-reporter-1-thread-1" 
 
Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "RequestHouseKeepingService" 
 
Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "http-nio-8000-ClientPoller"

通过日志大致猜测是内存方面的问题，可能是堆内存被用完了，一直不停的做 FGC，触发 Stop the world，同时由于内存不足，其他的线程无法分配到内存，也就无法进行任何工作。

hashtag
问题排查与分析

一般碰到问题，如果有监控的情况下，最好先去看一下监控指标，比如 Java 进程所在的那台机器的整体情况，JVM 的内存情况、Java 进程的 CPU 使用情况等，没有可视化监控也没关系，自己去搜集信息分析就可以了，有了可视化监控会更加方便，一般容器实例数量比较多时还是要借助可视化监控的。

首先去看一下 Java 进程异常的那台机器的整体情况，我们的服务是部署在 Kubernetes + Docker 中的

# 进入 Docker 容器执行 top
# 一般 jps、ps -ef | grep java、top
$ top
top - 10:26:07 up 1 day,  4:13,  0 users,  load average: 1.34, 1.37, 1.43
Tasks:  37 total,   1 running,  34 sleeping,   2 stopped,   0 zombie
%Cpu(s):  8.4 us,  0.6 sy,  0.0 ni, 90.8 id,  0.0 wa,  0.0 hi,  0.1 si,  0.0 st
KiB Mem : 32946036 total, 11481888 free, 12608160 used,  8855988 buff/cache
KiB Swap:        0 total,        0 free,        0 used. 19854660 avail Mem 

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                                                                                                                              
    1 root      20   0 13.716g 4.563g  16320 S 100.0 14.5   1297:10 java                                                                                                                                                 
 1741 root      20   0   42812   3460   2960 S   0.3  0.0   0:00.03 top                                                                                                                                                  
 1297 root      20   0    4296    728    640 S   0.0  0.0   0:00.00 sh                                                                                                                                                   
 1302 root      20   0    4296    124      0 S   0.0  0.0   0:00.00 sh                                                                                                                                                   
 1303 root      20   0   20696   2216   2020 S   0.0  0.0   0:00.00 script                                                                                                                                               
 1304 root      20   0    4296    764    680 S   0.0  0.0   0:00.00 sh                                                                                                                                                   
 1305 root      20   0   20144   3744   2992 S   0.0  0.0   0:00.00 bash    
 ...

可以看到 java 进程 CPU 占到 100%，可能是某个 Java 的线程比较活跃，而且平均负载并不高，问题不大。接着，查看 Java 进程中的线程使用内存和 CPU 的情况

可以看到 PID 是 12 的线程有嫌疑，以及 PID 是 7 的线程也有嫌疑，因为它的 TIME+ 列的值比较大，说明占用的 CPU 时间很长，473:08.60 表示多少呢？473分钟8秒600毫秒 (从右到左分别是百分之一秒，十分之一秒，秒，十秒，分钟)；继续来看这两个线程是什么？

看 nid=0xc 的那里是 VM Thread, "VM Thread" 是 JVM 自身启动的一个线程, 它主要用来协调其它线程达到安全点(Safepoint). 需要达到安全点的线程主要有: Stop the world 的 GC, 做 thread dump, 线程挂起以及偏向锁的撤销. 到这里我们基本可以猜测是和 GC 是有关的，我们再看 nid=0x7 Parallel GC Threads 和 nid=0xb G1 Parallel Marking Threads

接下来验证是 GC 问题的想法，查看 gc 情况

从执行结果可以看出 FGC 做了 4864 次，两次 FGC 之间隔了 14s，FGC 总共花了 68991s，也就是平均每次 FGC 花了 14s 左右，说明一次 FGC 做完，紧接着就继续做 FGC

也就是 FGC 远远超过 YGC，而且 FGC 的耗时再增加。极有可能是有大对象需要清除，或者内存泄漏等。我们还需要定位到具体占用内存的对象是哪个

通过堆信息我们可以分析出哪些对象占用了大量内存，进而关联到相关的代码，然后转到对应的代码去分析可能出现问题的地方。

通过 jvisualvm 来分析 dump 文件

总体视图
类和实例数的视图

可以看到差不多 60% 左右的内存都被 ArrayList, JsoupTextNode, TextNode, JsoupAttributs 等占用了，我们可以根据这些信息进一步定位到代码，然后去分析代码做了什么事情。

hashtag
总结

综合以上获得的信息，可以看出来垃圾收集器使用的 G1，配置的内存大小是 4G，被使用的对空间很接近 4G，所以 JVM 的堆中已经没有多余的内存分配给其他线程了，导致 JVM 的 0xc 和 0x7 两个线程在努力做 GC 的工作，而且这些被回收的对象都是大对象，没有办法直接释放，因为还在用，最终导致一直做 FGC，但是内存又没办法释放；此外，外部的请求到达服务时，服务由于没有内存可供分配，导致接口请求无法及时响应，外部服务调用后会报 Read Timeout。

从分析这个问题，也发现了自己在某些知识点上的不足，接下来要啃一下：

  1. G1 垃圾器不是很熟悉，如何应对这种场景下的问题，确实需要内存做计算，怎么合理选择垃圾收集器和配置参数

  2. 一开始解决这类问题有点蒙，还需要多积累经验，找讨论，边收集信息，边分析，边猜测，边决策下一步该怎么定位问题

hashtag
扩展

  • 查看 JVM 的启动参数等

  • Java 相关命令的参数含义

  • 堆内存统计

  • 在排查问题时出现 Can't attach to the process: ptrace(PTRACE_ATTACH, ..) failed for 1: Operation not permitted 的错误

我们使用了 Docker，jmap 等命令是在 Docker 容器内执行的，这是由于 Docker 自 1.10 版本开始加入的安全特性，类似于 jmap 这些 JDK 工具依赖于 Linux 的 PTRACE_ATTACH，而是 Docker 自 1.10 在默认的 seccomp 配置文件中禁用了 ptrace。解决办法是：

上一页Java 应用 CPU 100% 排查优化下一页导出优化

最后更新于