導火索
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還沒有應(yīng)答給用戶時空另，用戶斷掉連接造成的魄幕，大概率為客戶端連接超時自動斷開了陕贮。
第二個錯誤就比較迷了匣屡，這個錯誤是指找不到存活的后端server，但是網(wǎng)上查看引起這個錯誤的原因是多種多樣的女气。
多線并行
由于環(huán)境問題杏慰，取后端應(yīng)用日志比較耗時，在這期間利用如下命令寫了一個shell腳本觀察nginx服務(wù)器的端口連接情況
netstat -n | awk '/^tcp/ {++S[$NF]} END {for (a in S) print a, S[a]}'
通過腳本打印的日志發(fā)現(xiàn)，服務(wù)器有10幾秒的時間TIME_WAIT狀態(tài)的端口達到了28232缘滥，如下圖
通過以下命令查看本地端口范圍配置
cat /proc/sys/net/ipv4/ip_local_port_range
發(fā)現(xiàn)本地可使用的端口個數(shù)剛好為28232
也正是在這個時間段nginx開始不斷報錯
初步判斷是由于nginx服務(wù)器連接端口被用盡導致無法創(chuàng)建新的連接從而報錯
于是乎我找了一臺測試服務(wù)器做了個壓測轰胁，一分鐘壓了3W個請求，果然在請求到達2W+的時候ng開始報錯了朝扼。然而錯誤信息卻是如下：
[alert] 28637#0: *255914 socket() failed (24: Too many open files) while connecting to upstream
明顯跟我們之前遇到的報錯是有區(qū)別的软吐，同時我們nginx是做了雙中心，兩臺nginx的并發(fā)量存在明顯差異吟税，確都報了相同的錯誤。由此可以判斷并非高并發(fā)導致的服務(wù)器連接端口用盡姿现。
這個時候剛好我們也取下了后端應(yīng)用的日志肠仪，在對日志進行篩查后，發(fā)現(xiàn)了以下的報錯
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服務(wù)器在應(yīng)答時發(fā)現(xiàn)客戶端連接已經(jīng)關(guān)閉备典，想必是某種原因?qū)е路?wù)器響應(yīng)時間太長异旧，導致客戶端連接超時主動關(guān)閉。
柳暗花明
按照慣例提佣，我們應(yīng)該從以下角度開始排查為何服務(wù)器響應(yīng)會超時：
- 數(shù)據(jù)庫連接超時吮蛹、數(shù)據(jù)庫鎖
- 存在慢sql導致sql執(zhí)行超時、數(shù)據(jù)庫連接池阻塞
- 存在長時間的線程阻塞
- cpu超載拌屏、io_wait等
通過排查首先排除了數(shù)據(jù)庫方面的問題
監(jiān)控工具也沒有發(fā)現(xiàn)cpu和內(nèi)存異常的信息潮针，cpu load average也沒有異常
在linux下查看cpu和IO問題后，順便查看了一下JVM的內(nèi)存使用情況
使用命令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
突然發(fā)現(xiàn)倚喂，JVM的堆內(nèi)存老年代(Old Generation)高達近4個G每篷，使用率接近90%，嘴里不禁喃喃自語：“該GC了....”端圈，就在這句話脫口而出的時候焦读，腦海中突然靈光乍現(xiàn)，GC舱权，Stop the World 矗晃！
趕緊通過jstat -gcutil pid命令查看JVM的GC情況
由于當時是遠程機，所以沒有留下截圖宴倍，實際情況是Full GC進行了9次张症，總共耗時400多秒，平均FGC時間達到了50秒啊楚。（以上截圖已經(jīng)是第一次優(yōu)化后的結(jié)果了）
離了個大譜吠冤，眾所周知，Java程序在GC時會出現(xiàn)Stop the World恭理，這個時候程序處于暫停狀態(tài)
一切都解釋通了拯辙，當FULL GC長時間進行的時候，nginx對應(yīng)用的訪問就會出現(xiàn)以下錯誤
[error] 24826#0: *32502388 no live upstreams while connecting to upstream
當nginx和后端應(yīng)用建立好連接之后，后端應(yīng)用出現(xiàn)FULL GC涯保，導致長時間掛起诉濒，結(jié)果nginx訪問超時主動關(guān)閉了連接，然后后端應(yīng)用GC完畢之后繼續(xù)處理夕春，當準備返回應(yīng)答信息時未荒，就出現(xiàn)了以下錯誤
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上出現(xiàn)如下報錯：
[error] 24826#0: *32529323 upstream prematurely closed connection while reading response header from
為了進一步確定是否為GC STW導致的問題及志，我們選擇重啟了后端應(yīng)用片排，然后持續(xù)進行觀察
果然在沒有出現(xiàn)FGC的情況下，沒有出現(xiàn)任何錯誤速侈， 當錯誤出現(xiàn)之后率寡，發(fā)現(xiàn)已經(jīng)進行了一次FGC，由此基本判斷是由于FGC導致的問題倚搬， 接下來就是優(yōu)化JVM的問題了冶共。
