系统频繁full gc，导致接口访问超时问题排查过程

雨点打透心脏的1/2处 2023-03-02 13:24 0阅读 0赞

springboot系统，访问另一微服务接口时报超时。以下是问题排查过程。

[root@localhost xx-service]# top -Hp 25158
    
    top - 10:39:20 up 47 days, 24 min,  4 users,  load average: 3.20, 3.42, 3.30
    Threads: 105 total,   1 running, 104 sleeping,   0 stopped,   0 zombie
    %Cpu(s): 56.7 us,  0.2 sy,  0.0 ni, 43.2 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
    KiB Mem :  7814412 total,   550664 free,  4066692 used,  3197056 buff/cache
    KiB Swap:  7995388 total,  7818704 free,   176684 used.  3388156 avail Mem 
    
      PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND                                                                                                                                                                   
    25164 root      20   0 4728956   1.1g  24668 R 52.5 14.8   1026:30 java                                                                                                                                                                      
    25160 root      20   0 4728956   1.1g  24668 S 44.5 14.8 810:05.29 java                                                                                                                                                                      
    25161 root      20   0 4728956   1.1g  24668 S 43.5 14.8 809:54.96 java                                                                                                                                                                      
    25162 root      20   0 4728956   1.1g  24668 S 42.5 14.8 810:01.85 java                                                                                                                                                                      
    25163 root      20   0 4728956   1.1g  24668 S 41.9 14.8 810:10.74 java                                                                                                                                                                      
    25158 root      20   0 4728956   1.1g  24668 S  0.0 14.8   0:00.00 java                                                                                                                                                                      
    25159 root      20   0 4728956   1.1g  24668 S  0.0 14.8   0:12.39 java                                                                                                                                                                      
    25165 root      20   0 4728956   1.1g  24668 S  0.0 14.8   0:02.37 java                                                                                                                                                                      
    25166 root      20   0 4728956   1.1g  24668 S  0.0 14.8   0:00.69 java                                                                                                                                                                      
    25167 root      20   0 4728956   1.1g  24668 S  0.0 14.8   0:00.00 java                                                                                                                                                                      
    25168 root      20   0 4728956   1.1g  24668 S  0.0 14.8   1:01.03 java

25164这个线程占用cpu较高。

[root@localhost xx-service]# printf "%x\n" 25164
    624c
    
    [root@localhost xx-service]# jstack 25158|grep 624c
    "VM Thread" os_prio=0 tid=0x00007fb10413e000 nid=0x624c runnable

原来是VM Thread。这个线程就比较牛b了，是jvm里面的线程母体，根据hotspot源码（vmThread.hpp）里面的注释，它是一个单例的对象（最原始的线程）会产生或触发所有其他的线程，这个单个的VM线程是会被其他线程所使用来做一些VM操作（如，清扫垃圾等）。

再查看25160，25161，25162等几个占用cpu较高的线程，定位到类似这种：

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007fb10401e000 nid=0x6248 runnable

这是垃圾回收线程，该线程会负责进行垃圾回收。通常JVM会启动多个线程来处理这个工作，线程名称中\#后面的数字也会累加。

这说明垃圾回收线程占用大量cpu，也就是一直在执行垃圾回收操作，可能是某个空间快满了，jvm在垂死挣扎。

查看垃圾回收情况：

[root@localhost xx-service]# jstat -gc 25158 2s 10
     S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT   
    512.0  512.0   0.0    0.0   261120.0   0.0     262144.0   105567.2  131072.0 123327.4 15104.0 13852.5 716011 3256.054 714753 110712.027 113968.081
    512.0  512.0   0.0    0.0   261120.0   0.0     262144.0   105603.9  131072.0 123327.4 15104.0 13852.5 716022 3256.124 714764 110714.038 113970.162
    512.0  512.0   0.0    64.0  261120.0   0.0     262144.0   105581.3  131072.0 123327.4 15104.0 13852.5 716033 3256.187 714775 110715.947 113972.134
    512.0  512.0   0.0    0.0   261120.0   0.0     262144.0   105600.4  131072.0 123327.4 15104.0 13852.5 716045 3256.246 714787 110717.819 113974.065
    512.0  512.0   0.0    0.0   261120.0   0.0     262144.0   105584.9  131072.0 123327.4 15104.0 13852.5 716056 3256.309 714798 110719.682 113975.991
    512.0  512.0   0.0    0.0   261120.0   0.0     262144.0   105606.4  131072.0 123327.4 15104.0 13852.5 716068 3256.378 714810 110721.721 113978.099
    512.0  512.0   0.0    0.0   261120.0   0.0     262144.0   105557.1  131072.0 123327.4 15104.0 13852.5 716080 3256.437 714822 110723.699 113980.136
    512.0  512.0   0.0    0.0   261120.0   0.0     262144.0   105555.6  131072.0 123327.4 15104.0 13852.5 716092 3256.495 714834 110725.535 113982.030
    512.0  512.0   0.0    0.0   261120.0   0.0     262144.0   105552.0  131072.0 123327.4 15104.0 13852.5 716105 3256.558 714847 110727.536 113984.094
    512.0  512.0   0.0    32.0  261120.0   0.0     262144.0   105514.9  131072.0 123327.4 15104.0 13852.5 716117 3256.617 714859 110729.389 113986.006
    [root@localhost xx-service]# 
    [root@localhost xx-service]# jstat -gcutil 25158 2s 10
      S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT   
      0.00   0.00   0.00  40.25  94.09  91.71 716159 3256.828 714901 110735.842 113992.670
      0.00   6.25   0.00  40.25  94.09  91.71 716171 3256.886 714913 110737.707 113994.593
      0.00   6.25   0.00  40.24  94.09  91.71 716183 3256.957 714925 110739.797 113996.754
      0.00   6.25   0.00  40.24  94.09  91.71 716193 3257.021 714935 110741.615 113998.636
      0.00   0.00   0.00  40.25  94.09  91.71 716204 3257.094 714946 110743.652 114000.746
      0.00   0.00   0.00  40.25  94.09  91.71 716214 3257.160 714956 110745.545 114002.705
     31.25   0.00   0.00  40.25  94.09  91.71 716226 3257.233 714967 110747.480 114004.713
      0.00   0.00   0.00  40.23  94.09  91.71 716237 3257.295 714978 110749.341 114006.636
      0.00   0.00   0.00  40.23  94.09  91.71 716247 3257.359 714988 110751.210 114008.569
     25.00   0.00   0.00  40.23  94.09  91.71 716258 3257.426 714999 110753.236 114010.662
    
    [root@localhost xx-service]# jstat -gc 25158 2s 10
     S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT   
    512.0  512.0   0.0    0.0   261120.0   0.0     262144.0   113061.5  131072.0 123327.4 15104.0 13852.5 730632 3335.772 729346 113058.590 116394.363
    512.0  512.0   0.0    0.0   261120.0   0.0     262144.0   113061.6  131072.0 123327.4 15104.0 13852.5 730644 3335.845 729358 113060.555 116396.400
    512.0  512.0   0.0    0.0   261120.0   0.0     262144.0   113061.7  131072.0 123327.4 15104.0 13852.5 730656 3335.911 729370 113062.455 116398.366
    512.0  512.0   0.0   128.0  261120.0   0.0     262144.0   113061.8  131072.0 123327.4 15104.0 13852.5 730669 3335.981 729383 113064.488 116400.468
    512.0  512.0   0.0    32.0  261120.0   0.0     262144.0   113025.6  131072.0 123327.4 15104.0 13852.5 730681 3336.044 729395 113066.363 116402.407
    512.0  512.0   0.0    0.0   261120.0   0.0     262144.0   113040.4  131072.0 123327.4 15104.0 13852.5 730694 3336.107 729407 113068.378 116404.484
    512.0  512.0   0.0    0.0   261120.0   0.0     262144.0   113038.4  131072.0 123327.4 15104.0 13852.5 730706 3336.175 729420 113070.250 116406.426
    512.0  512.0   0.0    0.0   261120.0   0.0     262144.0   113038.5  131072.0 123327.4 15104.0 13852.5 730718 3336.240 729432 113072.101 116408.341
    512.0  512.0   0.0    0.0   261120.0   0.0     262144.0   113037.6  131072.0 123327.4 15104.0 13852.5 730730 3336.307 729444 113074.006 116410.312
    512.0  512.0   0.0    64.0  261120.0   0.0     262144.0   113037.7  131072.0 123327.4 15104.0 13852.5 730743 3336.375 729457 113076.029 116412.404

发现每一秒，YGC和FGC的次数都在疯狂增长。频繁FGC导致jvm 频繁stop the world，系统来不及响应请求，这就是访问接口超时的原因。

是什么导致频繁FGC？

从上面可以看到，年轻代老年代占用都很低，唯一就是metaspace占用很高，达到120M，而我们设置的metaspace大小是128M。

进一步查看堆占用：

[root@localhost xx-service]# jmap -heap 25158
    Attaching to process ID 25158, please wait...
    Debugger attached successfully.
    Server compiler detected.
    JVM version is 25.131-b11
    
    using thread-local object allocation.
    Parallel GC with 4 thread(s)
    
    Heap Configuration:
       MinHeapFreeRatio         = 0
       MaxHeapFreeRatio         = 100
       MaxHeapSize              = 536870912 (512.0MB)
       NewSize                  = 133693440 (127.5MB)
       MaxNewSize               = 268435456 (256.0MB)
       OldSize                  = 524288 (0.5MB)
       NewRatio                 = 2
       SurvivorRatio            = 8
       MetaspaceSize            = 134217728 (128.0MB)
       CompressedClassSpaceSize = 1073741824 (1024.0MB)
       MaxMetaspaceSize         = 134217728 (128.0MB)
       G1HeapRegionSize         = 0 (0.0MB)
    
    Heap Usage:
    PS Young Generation
    Eden Space:
       capacity = 267386880 (255.0MB)
       used     = 0 (0.0MB)
       free     = 267386880 (255.0MB)
       0.0% used
    From Space:
       capacity = 524288 (0.5MB)
       used     = 0 (0.0MB)
       free     = 524288 (0.5MB)
       0.0% used
    To Space:
       capacity = 524288 (0.5MB)
       used     = 0 (0.0MB)
       free     = 524288 (0.5MB)
       0.0% used
    PS Old Generation
       capacity = 268435456 (256.0MB)
       used     = 109205104 (104.14610290527344MB)
       free     = 159230352 (151.85389709472656MB)
       40.68207144737244% used

也能看到年轻年老占用都很低。唯一的可能就是metaspace了。

**但是metaspace快要耗尽，YGC怎么也疯狂增长呢，目前还想不通！**

metaspace设置了128M，根据以往观察，是够用的，这是测试环境，节省点吧。

还有其他什么原因？又分析了jstack日志，发现很多

> java.lang.Thread.State: BLOCKED

"http-nio-9060-exec-249" #402 daemon prio=5 os_prio=0 tid=0x00007fb0a4003800 nid=0x9db waiting for monitor entry [0x00007fb05ea7e000]
       java.lang.Thread.State: BLOCKED (on object monitor)
    	at java.lang.ClassLoader.loadClass(ClassLoader.java:404)
    	- waiting to lock <0x00000000e386a620> (a java.lang.Object)
    	at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:335)
    	at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
    	at java.lang.Class.forName0(Native Method)
    	at java.lang.Class.forName(Class.java:264)
    	at com.alibaba.druid.util.Utils.loadClass(Utils.java:203)
    	at com.alibaba.druid.util.MySqlUtils.getLastPacketReceivedTimeMs(MySqlUtils.java:351)
    
    省略。。。。。。
    
    "http-nio-9060-exec-246" #399 daemon prio=5 os_prio=0 tid=0x00007fb0c549c800 nid=0x9d3 runnable [0x00007fb05f084000]
       java.lang.Thread.State: RUNNABLE
    	at java.lang.Throwable.fillInStackTrace(Native Method)
    	at java.lang.Throwable.fillInStackTrace(Throwable.java:783)
    	- locked <0x00000000e6689358> (a java.lang.ClassNotFoundException)
    	at java.lang.Throwable.<init>(Throwable.java:287)
    	at java.lang.Exception.<init>(Exception.java:84)
    	at java.lang.ReflectiveOperationException.<init>(ReflectiveOperationException.java:75)
    	at java.lang.ClassNotFoundException.<init>(ClassNotFoundException.java:82)
    	at java.net.URLClassLoader.findClass(URLClassLoader.java:381)
    	at java.lang.ClassLoader.loadClass(ClassLoader.java:424)
    	- locked <0x00000000e386a620> (a java.lang.Object)
    	at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:335)
    	at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
    	at java.lang.Class.forName0(Native Method)
    	at java.lang.Class.forName(Class.java:348)
    	at org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader.loadFromParent(TomcatEmbeddedWebappClassLoader.java:112)
    	at org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader.doLoadClass(TomcatEmbeddedWebappClassLoader.java:85)
    	at org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader.loadClass(TomcatEmbeddedWebappClassLoader.java:68)
    	- locked <0x00000000e3472930> (a java.lang.Object)
    	at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1186)
    	at com.alibaba.druid.util.Utils.loadClass(Utils.java:211)
    	at com.alibaba.druid.util.MySqlUtils.getLastPacketReceivedTimeMs(MySqlUtils.java:351)
    	at com.alibaba.druid.pool.DruidAbstractDataSource.testConnectionInternal(DruidAbstractDataSource.java:1407)
    	at com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:1299)
    
    省略。。。。。。

多个线程waiting to lock <0x00000000e386a620>，另一个线程locked <0x00000000e386a620>却RUNNABLE。

且线程堆栈里都出现了

> com.alibaba.druid.util.MySqlUtils.getLastPacketReceivedTimeMs

至此，开始怀疑是druid配置有问题。网上搜索一番， 参考了

[https://www.oschina.net/question/1175066\_226318][https_www.oschina.net_question_1175066_226318]

[https://my.oschina.net/u/3434392/blog/3017866][https_my.oschina.net_u_3434392_blog_3017866]

[https://www.jianshu.com/p/fb27a87d189f][https_www.jianshu.com_p_fb27a87d189f]

说是要加上socketTimeout

> # 1.2 connectionProperties #
> 
> 参数是以键值对表示的字符串，其中可以配置 connectTimeout 和 socketTimeout，它们的单位都是毫秒，这两个参数在应对网络异常方面非常重要。
> 
> connectTimeout 配置建立 TCP 连接的超时时间。
> 
> socketTimeout 配置发送请求后等待响应的超时时间。这两个参数也可以通过在 jdbc url 中添加 connectTimeout=xxx&socketTimeout=xxx 的方式配置，试过在 connectinoProperties 中和 jdbc url 两个地方都配置，发现优先使用 connectionProperties 中的配置。
> 
> 如果不设置这两项超时时间，服务会有非常高的风险。现实案例是在网络异常后发现应用无法连接到 DB，但是重启后却能正常的访问 DB。
> 
> 因为在网络异常下 socket 没有办法检测到网络错误，这时连接其实已经变为“死连接”，如果没有设置 socket 网络超时，连接就会一直等待 DB 返回结果，造成新的请求都无法获取到连接。
> 
> > 推荐配置：socketTimeout=3000;connectTimeout=1200

加上后：

# 通过connectProperties属性来打开mergeSql功能；慢SQL记录
          connect-properties: druid.stat.mergeSql=true;druid.stat.slowSqlMillis=5000;socketTimeout=3000;connectTimeout=1200

试试看吧！

另外，发现一个挺好用的工具——tda，用来分析jstack非常好用。tda-bin-2.3.3.zip

通过tda可以看到，阻塞的线程是红色的。当你找到blocked的线程后，界面的下方，会打出阻塞的更详细的线程堆栈。

[https_www.oschina.net_question_1175066_226318]: https://www.oschina.net/question/1175066_226318
[https_my.oschina.net_u_3434392_blog_3017866]: https://my.oschina.net/u/3434392/blog/3017866
[https_www.jianshu.com_p_fb27a87d189f]: https://www.jianshu.com/p/fb27a87d189f