您好,登錄后才能下訂單哦!
本篇內(nèi)容主要講解“如何排查Kubernetes機(jī)器內(nèi)核問題”,感興趣的朋友不妨來看看。本文介紹的方法操作簡單快捷,實(shí)用性強(qiáng)。下面就讓小編來帶大家學(xué)習(xí)“如何排查Kubernetes機(jī)器內(nèi)核問題”吧!
在線上環(huán)境中的某個應(yīng)用出現(xiàn)了接口緩慢的問題!
就憑這個現(xiàn)象,能列出來的原因數(shù)不勝數(shù)。本篇博客主要敘述一下幾次排查以及最后如何確定原因的過程,可能不一定適用于其他集群,就當(dāng)是提供一個參考吧。排查過程比較冗長,過去太久了,我也不太可能回憶出所有細(xì)節(jié),希望大家見諒。
網(wǎng)絡(luò)請求流入集群時,對于我們集群的結(jié)構(gòu):
用戶請求=> Nginx => Ingress => uwsgi
不要問為什么有了 Ingress 還有 Nginx,這是歷史原因,有些工作暫時需要由 Nginx 承擔(dān)。
請求變慢一般馬上就會考慮,程序是不是變慢了,所以在發(fā)現(xiàn)問題后,首先在 uwsgi 中增加簡單的小接口,這個接口是處理快并且馬上返回數(shù)據(jù),然后定時請求該接口。在運(yùn)行幾天之后,確認(rèn)到該接口的訪問速度也很慢,排除程序中的問題,準(zhǔn)備在鏈路中查找原因。
由于我們的 Nginx 有 2 層,需要針對它們分別確認(rèn),看看究竟是哪一層慢了。請求量是比較大的,如果針對每個請求去查看,效率不高,而且有可能掩蓋真正原因,所以這個過程采用統(tǒng)計(jì)的方式。統(tǒng)計(jì)的方式是分別查看兩層 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" } } } ] } }
根據(jù) trace_id 可以獲取到 Nignx 日志以及 Ingress 日志,通過 ELK 的 API 獲得。
# 這個數(shù)據(jù)結(jié)構(gòu)用來記錄統(tǒng)計(jì)結(jié)果, # [[0, 0.1], 3]表示落在 0~0.1 區(qū)間的有 3 條記錄 # 因?yàn)樾?shù)的比較和區(qū)間比較麻煩,所以采用整數(shù),這里的 0~35 其實(shí)是 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ū)間段進(jìn)行數(shù)據(jù)統(tǒng)計(jì),可能有點(diǎn)羅嗦和重復(fù),我當(dāng)時做統(tǒng)計(jì)夠用了 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)計(jì)。
最后的統(tǒng)計(jì)結(jié)果大概如下:
我們總共有約 3000 條數(shù)據(jù)!
圖一:超過半數(shù)的請求落在 1 ~ 1.1s 區(qū)間,1s ~ 2s 的請求比較均勻,之后越來越少了。
圖二:大約 1/4 的請求其實(shí)已經(jīng)在 0.1s 內(nèi)返回了,但是 1 ~ 1.1s 也有 1/4 的請求落上去了,隨后的結(jié)果與圖一類似。
從圖 1 圖 2 結(jié)合來看,部分請求在 Ingress 側(cè)處理的時間其實(shí)比較短的。
圖三:比較明顯了,2/3 的請求在響應(yīng)時間方面能夠保持一致,1/3 的請求會有 1s 左右的延遲。
從統(tǒng)計(jì)結(jié)果來看,Nginx => Ingress 以及 Ingress => upstream,都存在不同程度的延遲,超過 1s 的應(yīng)用,大約有 2/3 的延遲來自 Ingress => upstream,1/3 的延遲來自 Nginx => Ingress。
抓包調(diào)查主要針對 Ingress => uwsgi,由于數(shù)據(jù)包延遲的情況只是偶發(fā)性現(xiàn)象,所以需要抓取所有的數(shù)據(jù)包再進(jìn)行過濾……這是一條請求時間較長的數(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ù)包
回顧一下 TCP 三次握手:
首先從 Ingress 側(cè)查看,連接在 21.585446 開始,22.588023 時,進(jìn)行了數(shù)據(jù)包重新發(fā)送的操作。
從 Node 側(cè)查看,Node 在 Ingress 數(shù)據(jù)包發(fā)出后不久馬上就收到了 syn,也立刻進(jìn)行了 syn 的返回,但是不知為何 1s 后才出現(xiàn)在 Ingress 處。
有一點(diǎn)比較令人在意,即便是數(shù)據(jù)包發(fā)生了重傳,但是也沒有出現(xiàn)丟包的問題,從兩臺機(jī)器數(shù)據(jù)包的流轉(zhuǎn)來看,此次請求中,大部分的時間是因?yàn)閿?shù)據(jù)包的延遲到達(dá)造成的,重傳只是表面現(xiàn)象,真正的問題是發(fā)生了數(shù)據(jù)包的延遲。
從隨機(jī)抓包的情況來看,不止是 SYN ACK 發(fā)生了重傳:
有些 FIN ACK 也會,數(shù)據(jù)包的延遲是有概率的行為!
單單看這個抓包可能只能確認(rèn)是發(fā)生了丟包,但是如果結(jié)合 Ingress 與 Nginx 的日志請求來看,如果丟包發(fā)生在 TCP 連接階段,那么在 Ingress 中,我們就可以查看 upstream_connect_time 這個值來大致估計(jì)下超時情況。當(dāng)時是這么整理的記錄:
我初步猜測這部分時間主要消耗在了 TCP 連接建立時,因?yàn)榻⑦B接的操作在兩次 Nginx 轉(zhuǎn)發(fā)時都存在,而我們的鏈路全部使用了短連接,下一步我準(zhǔn)備增加 $upstream_connect_time 變量,記錄建立連接花費(fèi)的時間。http://nginx.org/en/docs/http/ ... .html
既然可以了解到 TCP 連接的建立時間比較久,我們可以用它來作為一個衡量指標(biāo),我把 wrk 也修改了下,增加了對于連接時間的測量,具體的PR見這里,我們可以利用這一項(xiàng)指標(biāo)衡量后端的服務(wù)情況。
上面的工作前前后后我進(jìn)行了幾次,也沒有什么頭緒,遂找到公司的其他 Kubernetes 大佬咨詢問題,大佬提供了一個思路:
宿主機(jī)延遲也高的話,那就暫時排除宿主機(jī)到容器這條路徑。我們這邊此前排查過一個延遲問題, 是由于 Kubernetes 的監(jiān)控工具定期 cat proc 系統(tǒng)下的 cgroup 統(tǒng)計(jì)信息, 但由于 Docker 頻繁銷毀重建以及內(nèi)核 cache 機(jī)制,使得每次 cat 時間很長占用內(nèi)核導(dǎo)致網(wǎng)絡(luò)延遲, 可否排查一下你們的宿主機(jī)是否有類似情形? 不一定是 cgroup,其他需要頻繁陷入到內(nèi)核的操作都可能導(dǎo)致延遲很高。
這個跟我們排查的 cgroup 太像了,宿主機(jī)上有一些周期性任務(wù),隨著執(zhí)行次數(shù)增多,占用的內(nèi)核資源越來越多,達(dá)到一定程度就影響了網(wǎng)絡(luò)延遲。
大佬們也提供了一個內(nèi)核檢查工具(可以追蹤和定位中斷或者軟中斷關(guān)閉的時間):https://github.com/bytedance/trace-irqoff
有問題的 Ingress 機(jī)器的 latency 特別多,好多都是這樣的報錯,其他機(jī)器沒有這個日志:
而后,我針對機(jī)器中的 kubelet 進(jìn)行了一次追蹤,從火焰圖中可以確認(rèn),大量的時間耗費(fèi)在了讀取內(nèi)核信息中。
其中具體的代碼如下:
根據(jù)大佬所給的方向,基本能夠確定問題發(fā)生的真正原因:機(jī)器上定時任務(wù)的執(zhí)行過多,內(nèi)核緩存一直增加,導(dǎo)致內(nèi)核速度變慢了。它一變慢,引發(fā)了 TCP 握手時間變長,最后造成用戶體驗(yàn)下降。既然發(fā)現(xiàn)了問題,解決方案也比較容易搜索到了,增加任務(wù),檢查內(nèi)核是否變慢,慢了的話就清理一次:
sync && echo 3 > /proc/sys/vm/drop_caches
到此,相信大家對“如何排查Kubernetes機(jī)器內(nèi)核問題”有了更深的了解,不妨來實(shí)際操作一番吧!這里是億速云網(wǎng)站,更多相關(guān)內(nèi)容可以進(jìn)入相關(guān)頻道進(jìn)行查詢,關(guān)注我們,繼續(xù)學(xué)習(xí)!
免責(zé)聲明:本站發(fā)布的內(nèi)容(圖片、視頻和文字)以原創(chuàng)、轉(zhuǎn)載和分享為主,文章觀點(diǎn)不代表本網(wǎng)站立場,如果涉及侵權(quán)請聯(lián)系站長郵箱:is@yisu.com進(jìn)行舉報,并提供相關(guān)證據(jù),一經(jīng)查實(shí),將立刻刪除涉嫌侵權(quán)內(nèi)容。