記一次 Kubernetes 機器內(nèi)核問題排查
此次排查發(fā)生在 2020-11 月份，一直沒時間寫博客描述事情經(jīng)過，本次正好一起寫了吧。
具體現(xiàn)象
在線上環(huán)境中的某個應(yīng)用出現(xiàn)了接口緩慢的問題!
就憑這個現(xiàn)象，能列出來的原因數(shù)不勝數(shù)。本篇博客主要敘述一下幾次排查以及最后如何確定原因的過程，可能不一定適用于其他集群，就當是提供一個參考吧。排查過程比較冗長，過去太久了，我也不太可能回憶出所有細節(jié)，希望大家見諒。
網(wǎng)絡(luò)拓撲結(jié)構(gòu)
網(wǎng)絡(luò)請求流入集群時，對于我們集群的結(jié)構(gòu)：
- 用戶請求=> Nginx => Ingress => uwsgi
不要問為什么有了 Ingress 還有 Nginx，這是歷史原因，有些工作暫時需要由 Nginx 承擔。
初次定位
請求變慢一般馬上就會考慮，程序是不是變慢了，所以在發(fā)現(xiàn)問題后，首先在 uwsgi 中增加簡單的小接口，這個接口是處理快并且馬上返回數(shù)據(jù)，然后定時請求該接口。在運行幾天之后，確認到該接口的訪問速度也很慢，排除程序中的問題，準備在鏈路中查找原因。
再次定位 – 簡單的全鏈路數(shù)據(jù)統(tǒng)計
由于我們的 Nginx 有 2 層，需要針對它們分別確認，看看究竟是哪一層慢了。請求量是比較大的，如果針對每個請求去查看，效率不高，而且有可能掩蓋真正原因，所以這個過程采用統(tǒng)計的方式。統(tǒng)計的方式是分別查看兩層 Nginx 的日志情況。由于我們已經(jīng)在 ELK 上接入了日志，ELK 中篩選數(shù)據(jù)的腳本簡單如下：
- {
- "bool": {
- "must": [
- {
- "match_all": {}
- },
- {
- "match_phrase": {
- "app_name": {
- "query": "xxxx"
- }
- }
- },
- {
- "match_phrase": {
- "path": {
- "query": "/app/v1/user/ping"
- }
- }
- },
- {
- "range": {
- "request_time": {
- "gte": 1,
- "lt": 10
- }
- }
- },
- {
- "range": {
- "@timestamp": {
- "gt": "2020-11-09 00:00:00",
- "lte": "2020-11-12 00:00:00",
- "format": "yyyy-MM-dd HH:mm:ss",
- "time_zone": "+08:00"
- }
- }
- }
- ]
- }
- }
數(shù)據(jù)處理方案
根據(jù) trace_id 可以獲取到 Nignx 日志以及 Ingress 日志，通過 ELK 的 API 獲得。
- # 這個數(shù)據(jù)結(jié)構(gòu)用來記錄統(tǒng)計結(jié)果，
- # [[0, 0.1], 3]表示落在 0~0.1 區(qū)間的有 3 條記錄
- # 因為小數(shù)的比較和區(qū)間比較麻煩，所以采用整數(shù)，這里的 0~35 其實是 0~3.5s 區(qū)間
- # ingress_cal_map = [
- # [[0, 0.1], 0],
- # [[0.1, 0.2], 0],
- # [[0.2, 0.3], 0],
- # [[0.3, 0.4], 0],
- # [[0.4, 0.5], 0],
- # [[0.5, 1], 0],
- # ]
- ingress_cal_map = []
- for x in range(0, 35, 1):
- ingress_cal_map.append(
- [[x, (x+1)], 0]
- )
- nginx_cal_map = copy.deepcopy(ingress_cal_map)
- nginx_ingress_gap = copy.deepcopy(ingress_cal_map)
- ingress_upstream_gap = copy.deepcopy(ingress_cal_map)
- def trace_statisics():
- trace_ids = []
- # 這里的 trace_id 是提前查找過，那些響應(yīng)時間比較久的請求所對應(yīng)的 trace_id
- with open(trace_id_file) as f:
- data = f.readlines()
- for d in data:
- trace_ids.append(d.strip())
- cnt = 0
- for trace_id in trace_ids:
- try:
- access_data, ingress_data = get_igor_trace(trace_id)
- except TypeError as e:
- # 繼續(xù)嘗試一次
- try:
- access_data, ingress_data = get_igor_trace.force_refresh(trace_id)
- except TypeError as e:
- print("Can't process trace {}: {}".format(trace_id, e))
- continue
- if access_data['path'] != "/app/v1/user/ping": # 過濾臟數(shù)據(jù)
- continue
- if 'request_time' not in ingress_data:
- continue
- def get_int_num(data): # 數(shù)據(jù)統(tǒng)一做 *10 處理
- return int(float(data) * 10)
- # 針對每個區(qū)間段進行數(shù)據(jù)統(tǒng)計，可能有點羅嗦和重復(fù)，我當時做統(tǒng)計夠用了
- ingress_req_time = get_int_num(ingress_data['request_time'])
- ingress_upstream_time = get_int_num(ingress_data['upstream_response_time'])
- for cal in ingress_cal_map:
- if ingress_req_time >= cal[0][0] and ingress_req_time < cal[0][1]:
- cal[1] += 1
- break
- nginx_req_time = get_int_num(access_data['request_time'])
- for cal in nginx_cal_map:
- if nginx_req_time >= cal[0][0] and nginx_req_time < cal[0][1]:
- cal[1] += 1
- break
- gap = nginx_req_time - ingress_req_time
- for cal in nginx_ingress_gap:
- if gap >= cal[0][0] and gap <= cal[0][1]:
- cal[1] += 1
- break
- gap = ingress_req_time - ingress_upstream_time
- for cal in ingress_upstream_gap:
- if gap >= cal[0][0] and gap <= cal[0][1]:
- cal[1] += 1
- break
我分別針對 request_time(Nginx)，request_time(Ingress)以及 requet_time(nginx) - request_time(Ingress)做了統(tǒng)計。
最后的統(tǒng)計結(jié)果大概如下：
結(jié)果分析
我們總共有約 3000 條數(shù)據(jù)!
圖一：超過半數(shù)的請求落在 1 ~ 1.1s 區(qū)間，1s ~ 2s 的請求比較均勻，之后越來越少了。
圖二：大約 1/4 的請求其實已經(jīng)在 0.1s 內(nèi)返回了，但是 1 ~ 1.1s 也有 1/4 的請求落上去了，隨后的結(jié)果與圖一類似。
從圖 1 圖 2 結(jié)合來看，部分請求在 Ingress 側(cè)處理的時間其實比較短的。
圖三：比較明顯了，2/3 的請求在響應(yīng)時間方面能夠保持一致，1/3 的請求會有 1s 左右的延遲。
小結(jié)
從統(tǒng)計結(jié)果來看，Nginx => Ingress 以及 Ingress => upstream，都存在不同程度的延遲，超過 1s 的應(yīng)用，大約有 2/3 的延遲來自 Ingress => upstream，1/3 的延遲來自 Nginx => Ingress。
再深入調(diào)查 - 抓包處理
抓包調(diào)查主要針對 Ingress => uwsgi，由于數(shù)據(jù)包延遲的情況只是偶發(fā)性現(xiàn)象，所以需要抓取所有的數(shù)據(jù)包再進行過濾……這是一條請求時間較長的數(shù)據(jù)，本身這個接口返回應(yīng)該很快。
- {
- "_source": {
- "INDEX": "51",
- "path": "/app/v1/media/",
- "referer": "",
- "user_agent": "okhttp/4.8.1",
- "upstream_connect_time": "1.288",
- "upstream_response_time": "1.400",
- "TIMESTAMP": "1605776490465",
- "request": "POST /app/v1/media/ HTTP/1.0",
- "status": "200",
- "proxy_upstream_name": "default-prod-XXX-80",
- "response_size": "68",
- "client_ip": "XXXXX",
- "upstream_addr": "172.32.18.194:6000",
- "request_size": "1661",
- "@source": "XXXX",
- "domain": "XXX",
- "upstream_status": "200",
- "@version": "1",
- "request_time": "1.403",
- "protocol": "HTTP/1.0",
- "tags": ["_dateparsefailure"],
- "@timestamp": "2020-11-19T09:01:29.000Z",
- "request_method": "POST",
- "trace_id": "87bad3cf9d184df0:87bad3cf9d184df0:0:1"
- }
- }
Ingress 側(cè)數(shù)據(jù)包
uwsgi 側(cè)數(shù)據(jù)包
數(shù)據(jù)包流轉(zhuǎn)情況
回顧一下 TCP 三次握手：
首先從 Ingress 側(cè)查看，連接在 21.585446 開始，22.588023 時，進行了數(shù)據(jù)包重新發(fā)送的操作。
從 Node 側(cè)查看，Node 在 Ingress 數(shù)據(jù)包發(fā)出后不久馬上就收到了 syn，也立刻進行了 syn 的返回，但是不知為何 1s 后才出現(xiàn)在 Ingress 處。
有一點比較令人在意，即便是數(shù)據(jù)包發(fā)生了重傳，但是也沒有出現(xiàn)丟包的問題，從兩臺機器數(shù)據(jù)包的流轉(zhuǎn)來看，此次請求中，大部分的時間是因為數(shù)據(jù)包的延遲到達造成的，重傳只是表面現(xiàn)象，真正的問題是發(fā)生了數(shù)據(jù)包的延遲。
不止是 ACK 數(shù)據(jù)包發(fā)生了延遲
從隨機抓包的情況來看，不止是 SYN ACK 發(fā)生了重傳：
有些 FIN ACK 也會，數(shù)據(jù)包的延遲是有概率的行為!
小結(jié)
單單看這個抓包可能只能確認是發(fā)生了丟包，但是如果結(jié)合 Ingress 與 Nginx 的日志請求來看，如果丟包發(fā)生在 TCP 連接階段，那么在 Ingress 中，我們就可以查看 upstream_connect_time 這個值來大致估計下超時情況。當時是這么整理的記錄：
我初步猜測這部分時間主要消耗在了 TCP 連接建立時，因為建立連接的操作在兩次 Nginx 轉(zhuǎn)發(fā)時都存在，而我們的鏈路全部使用了短連接，下一步我準備增加 $upstream_connect_time 變量，記錄建立連接花費的時間。http://nginx.org/en/docs/http/ ... .html
后續(xù)工作
既然可以了解到 TCP 連接的建立時間比較久，我們可以用它來作為一個衡量指標，我把 wrk 也修改了下，增加了對于連接時間的測量，具體的PR見這里，我們可以利用這一項指標衡量后端的服務(wù)情況。
尋找大佬，看看是否遇到類似問題
上面的工作前前后后我進行了幾次，也沒有什么頭緒，遂找到公司的其他 Kubernetes 大佬咨詢問題，大佬提供了一個思路：
宿主機延遲也高的話，那就暫時排除宿主機到容器這條路徑。我們這邊此前排查過一個延遲問題， 是由于 Kubernetes 的監(jiān)控工具定期 cat proc 系統(tǒng)下的 cgroup 統(tǒng)計信息， 但由于 Docker 頻繁銷毀重建以及內(nèi)核 cache 機制，使得每次 cat 時間很長占用內(nèi)核導(dǎo)致網(wǎng)絡(luò)延遲， 可否排查一下你們的宿主機是否有類似情形? 不一定是 cgroup，其他需要頻繁陷入到內(nèi)核的操作都可能導(dǎo)致延遲很高。
這個跟我們排查的 cgroup 太像了，宿主機上有一些周期性任務(wù)，隨著執(zhí)行次數(shù)增多，占用的內(nèi)核資源越來越多，達到一定程度就影響了網(wǎng)絡(luò)延遲。
大佬們也提供了一個內(nèi)核檢查工具(可以追蹤和定位中斷或者軟中斷關(guān)閉的時間)：https://github.com/bytedance/trace-irqoff
有問題的 Ingress 機器的 latency 特別多，好多都是這樣的報錯，其他機器沒有這個日志：
而后，我針對機器中的 kubelet 進行了一次追蹤，從火焰圖中可以確認，大量的時間耗費在了讀取內(nèi)核信息中。
其中具體的代碼如下：
小結(jié)
根據(jù)大佬所給的方向，基本能夠確定問題發(fā)生的真正原因：機器上定時任務(wù)的執(zhí)行過多，內(nèi)核緩存一直增加，導(dǎo)致內(nèi)核速度變慢了。它一變慢，引發(fā)了 TCP 握手時間變長，最后造成用戶體驗下降。既然發(fā)現(xiàn)了問題，解決方案也比較容易搜索到了，增加任務(wù)，檢查內(nèi)核是否變慢，慢了的話就清理一次：
sync && echo 3 > /proc/sys/vm/drop_caches
總結(jié)
這次的排查過程是由于應(yīng)用層出現(xiàn)了影響用戶體驗的問題后，進一步延伸到了網(wǎng)絡(luò)層，其中經(jīng)歷了漫長的抓包過程，也增加了自己的腳本用于指標衡量，隨后又通過內(nèi)核工具定位到了具體應(yīng)用，最后再根據(jù)應(yīng)用的 pprof 工具制作出的火焰圖定位到了更加精確的異常位置，期間自己一個人沒法處理問題，遂請其他大佬來幫忙，大佬們見多識廣，可以給出一些可能性的猜想，還是很有幫助的。
當你發(fā)現(xiàn)某臺機器無論做什么都慢，而 CPU 和內(nèi)核卻不是瓶頸的時候，那有可能是內(nèi)核慢了。
希望本文能對大家未來排查集群問題時有所幫助。
