导火索
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，如下图
通过以下命令查看本地端口范围配置
cat /proc/sys/net/ipv4/ip_local_port_range
发现本地可使用的端口个数刚好为28232
也正是在这个时间段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情况
由于当时是远程机，所以没有留下截图，实际情况是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的问题了。
