记一次Full GC导致的线上问题

导火索

nginx报502
先查看了一下ng的错误日志，有如下两种类型的报错：

 [error] 24826#0: *32529323 upstream prematurely closed connection while reading response header from upstream

 [error] 24826#0: *32502388 no live upstreams while connecting to upstream

第一个错误是由于upstream还没有应答给用户时，用户断掉连接造成的，大概率为客户端连接超时自动断开了。
第二个错误就比较迷了，这个错误是指找不到存活的后端server，但是网上查看引起这个错误的原因是多种多样的。

多线并行

由于环境问题，取后端应用日志比较耗时，在这期间利用如下命令写了一个shell脚本观察nginx服务器的端口连接情况

netstat -n | awk '/^tcp/ {++S[$NF]} END {for (a in S) print a, S[a]}'

通过脚本打印的日志发现，服务器有10几秒的时间TIME_WAIT状态的端口达到了28232，如下图

6a9b8046d1ff80facfcb4d96fa48680.png

通过以下命令查看本地端口范围配置

cat /proc/sys/net/ipv4/ip_local_port_range

发现本地可使用的端口个数刚好为28232

image.png

也正是在这个时间段nginx开始不断报错

初步判断是由于nginx服务器连接端口被用尽导致无法创建新的连接从而报错

于是乎我找了一台测试服务器做了个压测，一分钟压了3W个请求，果然在请求到达2W+的时候ng开始报错了。然而错误信息却是如下：

 [alert] 28637#0: *255914 socket() failed (24: Too many open files) while connecting to upstream

明显跟我们之前遇到的报错是有区别的，同时我们nginx是做了双中心，两台nginx的并发量存在明显差异，确都报了相同的错误。由此可以判断并非高并发导致的服务器连接端口用尽。

这个时候刚好我们也取下了后端应用的日志，在对日志进行筛查后，发现了以下的报错

Caused by: java.io.IOException: Broken pipe
    at sun.nio.ch.FileDispatcherImpl.write0(Native Method) ~[?:1.8.0_171]
    at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47) ~[?:1.8.0_171]
    at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93) ~[?:1.8.0_171]
    at sun.nio.ch.IOUtil.write(IOUtil.java:65) ~[?:1.8.0_171]
    at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471) ~[?:1.8.0_171]
    at org.apache.tomcat.util.net.NioChannel.write(NioChannel.java:136) ~[tomcat-coyote.jar:8.5.55]
    at org.apache.tomcat.util.net.NioBlockingSelector.write(NioBlockingSelector.java:101) ~[tomcat-coyote.jar:8.5.55]
    at org.apache.tomcat.util.net.NioSelectorPool.write(NioSelectorPool.java:157) ~[tomcat-coyote.jar:8.5.55]
    at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.doWrite(NioEndpoint.java:1312) ~[tomcat-coyote.jar:8.5.55]
    at org.apache.tomcat.util.net.SocketWrapperBase.doWrite(SocketWrapperBase.java:692) ~[tomcat-coyote.jar:8.5.55]
    at org.apache.tomcat.util.net.SocketWrapperBase.flushBlocking(SocketWrapperBase.java:645) ~[tomcat-coyote.jar:8.5.55]
    at org.apache.tomcat.util.net.SocketWrapperBase.flush(SocketWrapperBase.java:635) ~[tomcat-coyote.jar:8.5.55]
    at org.apache.coyote.http11.Http11OutputBuffer$SocketOutputBuffer.flush(Http11OutputBuffer.java:646) ~[tomcat-coyote.jar:8.5.55]
    at org.apache.coyote.http11.filters.IdentityOutputFilter.flush(IdentityOutputFilter.java:160) ~[tomcat-coyote.jar:8.5.55]
    at org.apache.coyote.http11.Http11OutputBuffer.flush(Http11OutputBuffer.java:252) ~[tomcat-coyote.jar:8.5.55]
    at org.apache.coyote.http11.Http11Processor.flush(Http11Processor.java:1392) ~[tomcat-coyote.jar:8.5.55]
    at org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:404) ~[tomcat-coyote.jar:8.5.55]
    at org.apache.coyote.Response.action(Response.java:206) ~[tomcat-coyote.jar:8.5.55]
    at org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:326) ~[catalina.jar:8.5.55]
    ... 60 more

这个错误是由于tomcat服务器在应答时发现客户端连接已经关闭，想必是某种原因导致服务器响应时间太长，导致客户端连接超时主动关闭。

柳暗花明

按照惯例，我们应该从以下角度开始排查为何服务器响应会超时：

• 数据库连接超时、数据库锁
• 存在慢sql导致sql执行超时、数据库连接池阻塞
• 存在长时间的线程阻塞
• cpu超载、io_wait等

通过排查首先排除了数据库方面的问题

监控工具也没有发现cpu和内存异常的信息，cpu load average也没有异常

在linux下查看cpu和IO问题后，顺便查看了一下JVM的内存使用情况

使用命令jmap -heap pid 查看如下：

Attaching to process ID 1, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.171-b11

using thread-local object allocation.
Parallel GC with 43 thread(s)

Heap Configuration:
   MinHeapFreeRatio         = 0
   MaxHeapFreeRatio         = 100
   MaxHeapSize              = 17179869184 (16384.0MB)
   NewSize                  = 89128960 (85.0MB)
   MaxNewSize               = 5726273536 (5461.0MB)
   OldSize                  = 179306496 (171.0MB)
   NewRatio                 = 2
   SurvivorRatio            = 8
   MetaspaceSize            = 21807104 (20.796875MB)
   CompressedClassSpaceSize = 1073741824 (1024.0MB)
   MaxMetaspaceSize         = 17592186044415 MB
   G1HeapRegionSize         = 0 (0.0MB)

Heap Usage:
PS Young Generation
Eden Space:
   capacity = 4995416064 (4764.0MB)
   used     = 371647312 (354.4304962158203MB)
   free     = 4623768752 (4409.56950378418MB)
   7.439766923086069% used
From Space:
   capacity = 363331584 (346.5MB)
   used     = 341794088 (325.96024322509766MB)
   free     = 21537496 (20.539756774902344MB)
   94.07222026698345% used
To Space:
   capacity = 365428736 (348.5MB)
   used     = 0 (0.0MB)
   free     = 365428736 (348.5MB)
   0.0% used
PS Old Generation
   capacity = 3899129856 (3718.5MB)
   used     = 3334968784 (3180.474075317383MB)
   free     = 564161072 (538.0259246826172MB)
   85.53110327598179% used

突然发现，JVM的堆内存老年代(Old Generation)高达近4个G，使用率接近90%，嘴里不禁喃喃自语：“该GC了....”，就在这句话脱口而出的时候，脑海中突然灵光乍现，GC，Stop the World ！
赶紧通过jstat -gcutil pid命令查看JVM的GC情况

6fd0d284bc7ce6df2120c087c140ac5.png

由于当时是远程机，所以没有留下截图，实际情况是Full GC进行了9次，总共耗时400多秒，平均FGC时间达到了50秒。（以上截图已经是第一次优化后的结果了）

离了个大谱，众所周知，Java程序在GC时会出现Stop the World，这个时候程序处于暂停状态

一切都解释通了，当FULL GC长时间进行的时候，nginx对应用的访问就会出现以下错误

 [error] 24826#0: *32502388 no live upstreams while connecting to upstream

当nginx和后端应用建立好连接之后，后端应用出现FULL GC，导致长时间挂起，结果nginx访问超时主动关闭了连接，然后后端应用GC完毕之后继续处理，当准备返回应答信息时，就出现了以下错误

Caused by: java.io.IOException: Broken pipe
    at sun.nio.ch.FileDispatcherImpl.write0(Native Method) ~[?:1.8.0_171]
    at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47) ~[?:1.8.0_171]
    at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93) ~[?:1.8.0_171]
    at sun.nio.ch.IOUtil.write(IOUtil.java:65) ~[?:1.8.0_171]
    at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471) ~[?:1.8.0_171]
    at org.apache.tomcat.util.net.NioChannel.write(NioChannel.java:136) ~[tomcat-coyote.jar:8.5.55]

同时如果浏览器的连接请求先超时，则会在nginx上出现如下报错：

[error] 24826#0: *32529323 upstream prematurely closed connection while reading response header from 

为了进一步确定是否为GC STW导致的问题，我们选择重启了后端应用，然后持续进行观察

果然在没有出现FGC的情况下，没有出现任何错误， 当错误出现之后，发现已经进行了一次FGC，由此基本判断是由于FGC导致的问题， 接下来就是优化JVM的问题了。