no.1
及時止損
看現象是個别實例集中(zhōng)出現,不是全部實例出現,那就和運行環境、流量、或者某個資(zī)源有關系。按照及時止損的原則,首先驗證重啟能否恢複,驗證重啟可以恢複,聯系OPS快速操作重啟,服務恢複。由于不是穩定複現問題,需要保留現場用于問題定位,讓OPS保留兩個故障實例,用作問題定位(保留的實例臨時屏蔽流量)。
重啟大(dà)法快速完成止損,服務恢複,觀察段時間運行穩定。然後可以不慌不忙定位問題了。
no.2
問題定位
1.客戶端請求出現connection reset by peer,驗證問題實例穩定複現。
curl -v 'http://10.xx.xx.35:2133/xx/xx/checkalive'
2.查看日志(zhì),并沒有access日志(zhì)輸出,而且響應connection reset by peer。
tail -f ./log/xxx.log
3.通過tcpdump查看請求詳細數據包情況(有些機器tcpdump按照路徑沒有在PATH裡,可以通過whereis檢索下(xià)具體(tǐ)按照路徑使用,通過ifconfig查看網絡設備名)。通過tcpdump結果發現,TCP三次握手完成,在發送數據時服務端沒有響應ACK,而響應了reset,導緻客戶端http請求響應connection reset by peer。
whereis tcpdump</code>`tcpdump: /usr/sbin/tcpdump /usr/share/man/man8/tcpdump.8.gz /usr/share/man/man1/tcpdump.1 /usr/share/man/man1/tcpdump.1.gz````ifconfig``eth0 Link encap:Ethernet``lo Link encap:Local Loopback````/usr/sbin/tcpdump -i eth0 -n -nn host 10.xx.xx.35```<code style='border-radius: 0px;white-space: pre;display: flex;font-family: Consolas, "Liberation Mono", Menlo, Courier, monospace;'>發現TCP三次握手完成,在發送數據時服務端沒有響應ACK,而響應了reset,導緻客戶端http請求響應connection reset by peer。
4.服務端通過listen(sockfd, backlog)方法告訴内核監聽(tīng)該socket并設置隊列大(dà)小(xiǎo)(未完成鍊接隊列+已完成連接隊列),然後當客戶端通過connect()方法請求鍊接時,由系統内核完成TCP三次握手,并把請求放(fàng)入已完成連接隊列,等待調用accept()方法取走,accept()需要先通過socket()創建新的句柄。
golang實現是:框架通過net/http包Server.Serve()方法開(kāi)啟服務,标準庫中(zhōng)通過net包TCPListener.AcceptTCP()等待獲取新的鍊接,最終通過internal/poll包的accept()發起系統調用accept4() or accept(),golang這個accept和c的accept()還不一(yī)樣,golang不需要提前創建套接字句柄傳入,而且由accept()直接返回新套接字句柄。
也就是客戶端請求時,内核完成了TCP三次握手,并把請求放(fàng)入已完成連接隊列,但是accept時發生(shēng)了錯誤,直接響應了客戶端reset。accept發生(shēng)錯誤最常見就是句柄被打滿了,查看進程監聽(tīng)端口鍊接情況和進程句柄使用情況。
net/http/server.go func (srv *Server) Serve(l net.Listener) error</code>`net/tcpsock.go func (l *TCPListener) AcceptTCP() (*TCPConn, error)``net/tcpsock_posix.go func (ln *TCPListener) accept() (*TCPConn, error)``net/fd_unix.go func (fd *netFD) accept() (netfd *netFD, err error)``internal/poll/fd_unix.go func (fd *FD) Accept() (int, syscall.Sockaddr, string, error)`<code style='border-radius: 0px;white-space: pre;display: flex;font-family: Consolas, "Liberation Mono", Menlo, Courier, monospace;'>internal/poll/sock_cloexec.go func accept(s int) (int, syscall.Sockaddr, string, error)
5.通過netstat or ss查看監聽(tīng)端口的鍊接情況,通過lsof查看進程句柄占用情況,通過ulimit查看系統限制。發現果然進程句柄被打滿了,超過了10240的限制。确認是由于進程句柄被打滿導緻客戶端請求響應connection reset by peer。同時通過netstat的統計信息還發現,處于CLOSE_WAIT狀态的鍊接很多,但是也遠小(xiǎo)于打開(kāi)的句柄數。至此,雖然明确了客戶端請求會響應connection reset by peer是由于服務進程句柄被打滿導緻的,但是依然不知(zhī)道什麼原因導緻了服務進程句柄被打滿。
netstat -an | grep port 或者 ss -ant | grep port</code>`lsof -p port`<code style='border-radius: 0px;white-space: pre;display: flex;font-family: Consolas, "Liberation Mono", Menlo, Courier, monospace;'>ulimit -a
6.CLOSE_WAIT狀态鍊接太多,可能會占用大(dà)量句柄,從CLOSE_WAIT狀态入手分(fēn)析。結合TCP狀态機,四次揮手過程中(zhōng),被動關閉的一(yī)方收到第一(yī)次斷開(kāi)鍊接的FIN包後進入CLOSE_WAIT狀态,等待發送完數據,然後發出第二次FIN包後進入LAST_ACK狀态,收到對端ACK後進入CLOSED狀态完成,另外(wài)CLOSE_WAIT狀态有超時時間(一(yī)般默認是2H),超時會被系統關閉。三次握手是在系統内核完成的,但是四次揮手由于要等待數據發送完成,是和應用程序相關的,内核收到第一(yī)個FIN後會通知(zhī)應用程序,應該是應用程序要響應後才能再發送第二個FIN。
結合這些信息猜測:服務句柄是被逐漸累積打滿的,出現大(dà)量CLOSE_WAIT是由于客戶端先斷開(kāi)鍊接(很可能是請求超時),服務端在收到客戶端超時端口請求後,由于用戶态請求處理阻塞,導緻第二次FIN無法發送,而且應該是出現了死鎖等問題,持久阻塞(句柄一(yī)緻沒有被釋放(fàng))。客戶端應該是先有大(dà)量io timeout,等服務端句柄被打滿後才出現connect reset by peer的,而客戶端io timeout增多很可能是服務端處理請求耗時突增或者阻塞導緻。
理論上能解釋通了,線下(xià)模拟實現驗證,在接口中(zhōng)sleep(100s),壓測很快就複現了connect reset by peer,現象和線上問題case完全一(yī)緻,确認猜想。那麼接下(xià)來定位的重點就是為什麼服務端會突然出現阻塞?由于不穩定複現,是什麼觸發了阻塞?
SOCKET工(gōng)作流程
epoll
TCP狀态流轉圖:
TCP SOCKET狀态表:
·CLOSED: 關閉狀态,沒有連接活動
·LISTEN: 監聽(tīng)狀态,服務器正在等待連接進入
·SYN_SENT: 已經發出連接請求,等待确認
·SYN_RCVD: 收到一(yī)個連接請求,尚未确認
·ESTABLISHED: 連接建立,正常數據傳輸狀态
·FIN_WAIT_1:(主動關閉)已經發送關閉請求,等待确認
·FIN_WAIT_2:(主動關閉)收到對方關閉确認,等待對方關閉請求
·CLOSE_WAIT:(被動關閉)收到對方關閉請求,已經确認
·LAST_ACK: (被動關閉)等待最後一(yī)個關閉确認,并等待所有分(fēn)組死掉
·TIMED_WAIT: 完成雙向關閉,等待所有分(fēn)組死掉
·CLOSING: 雙方同時嘗試關閉,等待對方确認
三次握手
四次揮手
7.到了應用程序層面,要分(fēn)析進程過去(qù)發生(shēng)了什麼,隻能從應用日志(zhì)和服務監控入手了,從曆史監控曲線(内存、句柄、流量、耗時等)查找可能出現異常的時間點,再找關鍵時間點的日志(zhì)仔細分(fēn)析。發現剛開(kāi)始是處理耗時增長,然後隻能輸出access_log,最後才到請求無日志(zhì)輸出,從日志(zhì)完成驗證上面的分(fēn)析猜想。發現耗時突增是關鍵點,仔細分(fēn)析業務日志(zhì),發現是請求DB耗時增加,再進一(yī)步看訪問DB的統計信息,發現DB連接池一(yī)直在被打滿,請求排隊等空閑待鍊接,導緻請求處理耗時增加,然後排隊請求越來越多,直到句柄數被打滿。由于DB連接池新建鍊接需要句柄,句柄被排隊等空閑鍊接的請求給打滿了,形成了死鎖。也就出現了從超時到句柄被打滿還無法釋放(fàng)的情況。線上環境修改DB連接池配置,壓測果然很快複現了。至此,終于發現了真相(哭暈,再次證明了完善的日志(zhì)和監控的重要性)。
type DBStats struct {</code>` MaxOpenConnections int // Maximum number of open connections to the database; added in Go 1.11```` // Pool Status`` OpenConnections int // The number of established connections both in use and idle.`` InUse int // The number of connections currently in use; added in Go 1.11`` Idle int // The number of idle connections; added in Go 1.11```` // Counters`` WaitCount int64 // The total number of connections waited for; added in Go 1.11`` WaitDuration time.Duration // The total time blocked waiting for a new connection; added in Go 1.11`` MaxIdleClosed int64 // The total number of connections closed due to SetMaxIdleConns; added in Go 1.11`` MaxLifetimeClosed int64 // The total number of connections closed due to SetConnMaxLifetime; added in Go 1.11`<code style='border-radius: 0px;white-space: pre;display: flex;font-family: Consolas, "Liberation Mono", Menlo, Courier, monospace;'>}
no.3
故障原因
為了防止DB鍊接數被打滿,剛開(kāi)始DB連接池最大(dà)連接數配置的比較小(xiǎo),流量慢(màn)慢(màn)上漲逼近平衡點。當天由于運營活動稍微增加的點流量就成了壓死駱駝的最後一(yī)根稻草,導緻查詢DB請求排隊等待空閑鍊接,排隊時間越長積壓的請求越多,請求處理耗時越大(dà),直到積壓請求太多把句柄打滿,出現了死鎖。
複現驗證
修改DB最大(dà)連接數配置壓測,很快就能複現。
問題修複
去(qù)掉DB連接池最大(dà)連接數限制。
no.4
總結反思
線上故障處理原則
1.及時通報,及時止損。
2.保留現場,定位問題。
3.徹底修複,故障總結。
線上問題分(fēn)析
先初步收集信息,再根據收集到的有限的信息推斷可能的真相,再定向尋找證據證明自己的推斷,再設計實驗模拟複現确認自己的推斷。
絕大(dà)部分(fēn)問題都是可以通過模拟複現的,隻是有些問題找到一(yī)條正确複現的路徑比較費(fèi)勁,找到這條複現路徑也就基本能發現問題了。通常是應用系統提供的相應工(gōng)具分(fēn)析問題case,獲取詳細的信息,根據這些信息結合相關知(zhī)識,推斷造成這個現象可能的原因,設計複現的途徑,然後開(kāi)發機模拟實驗确認問題。
不能複現的問題可能和流量、機器的瞬時環境、依賴服務的瞬時抖動等有關系,處理這類問題完善的監控和日志(zhì)就非常重要了,服務上線後要接入相關機器資(zī)源、流量、錯誤的監控,開(kāi)發時日志(zhì)記錄要完善。日志(zhì)通常是定位線上問題最重要也最高效的方式,開(kāi)發階段一(yī)定要重視日志(zhì)。
一(yī)般是從問題表象切入,結合問題表象和相關知(zhī)識,尋找方向,逐個深入分(fēn)析确認疑點,逐步找到那個最可能的原因。